• Resolved Awaken Solutions Inc.

    (@awakensolutions)


    Hello. Longtime Pods fan. Onetime ‘Friend of Pods’ monthly donor.

    I have a client site that has been using Pods and GravityForms for about 6 years now. Recently when we try to access the “Reservations” Pod page in the admin section, it times out after trying for about a minute. I have tested with all functions.php lines removed, the default theme and all plugins disabled except Pods and Gravity forms (both latest versions as of 2023-12-29) and the issue still happens. If I disable GravityForms then I can load the Reservations page without trouble.

    I opened a ticket with GravityForms and exchanged some helpful emails with Jim True (who I used to chat with at Pods!) but he suggested I should ask Pods for support. He also suggested I setup a staging site, preferably not on my dedicated server which hosts the live site, so I have done that now on a new WP Engine plan. And the issue persists there, suggesting it is not a a problem with my servers or databases.

    I tried debugging using querymonitor but since the problem is a timeout I am unable to diagnose anything with that.

    I can provide all credentials to the WP Engine account if you don’t mind suggesting to me the best way to do that.

    Thanks in advance.

Viewing 13 replies - 1 through 13 (of 13 total)
  • Plugin Author Scott Kingsley Clark

    (@sc0ttkclark)

    I haven’t seen this on my Pods related sites with GF yet.

    Could you please provide your Site Health information to help us determine what might be causing this problem? To get that, you can go to your WordPress dashboard area and go to: Tools > Site Health > Info, then Press the “Copy site info to clipboard” button, and paste the results here.

    Thread Starter Awaken Solutions Inc.

    (@awakensolutions)

    Thanks for the quick reply Scott, and happy new year.

    Here it is: https://gist.github.com/GitHubGreg/ac65c7a6afd8ae347318babc2c445c5e

    Plugin Support Paul Clark

    (@pdclark)

    Hi @awakensolutions,

    Since the core issue is a timeout, here are some thoughts and things to check:

    • Perhaps easiest to test in a development environment — but both WPEngine and Cloudflare will terminate a process if it takes too long. Both platforms are tuned to be maximally responsive, which involves turning off anything that runs too long. Cloudflare will timeout at 100 seconds if no output is sent, but WPEngine does not allow any PHP request to take more than 60 seconds.
    • Without knowing what is on the specific Reservations admin page, I would take a guess that there might be a field which queries user accounts. The health check says the site has 2,658 user accounts. If that many users, especially with their profile information, is queried all at once, rather than with a page-limited AJAX search, it could cause such a timeout.
    • If there is not a user field, consider any other fields, such as content generated by those users, which might be even more processor intensive. The thing to look for and consider is if any menu item is loading hundreds or thousands of content items up-front; anything that might take longer than 60 seconds for a typical single-threaded database request to get through.
    Thread Starter Awaken Solutions Inc.

    (@awakensolutions)

    Thanks for the reply Paul.

    I tested on my own server before creating the WP Engine staging environment and it would never resolve no matter how long I extended the timeout limit.

    Yes, there is indeed a field tied to Users, it is the “Billing contact” field. Please see here for the following screenshots:

    • 01 Fields
    • 02 Field details
    • 03 Relationship options
    • 04 Advanced
    • 05 Conditional logic

    The first screenshot is all the fields for the “Reservation” Pod. The other screenshots are the specific settings for the “Billing contact” field.

    I removed the “Billing contact” field from the “Admin UI” settings of the Pod (both from “Admin Table Columns” and “Search Filters”) but it didn’t help.

    There are no custom functions running on the Reservations page. I removed all functions, disabled all plugins except Pods and Gravity Forms, and set the default WordPress theme.

    Importantly, as mentioned, the “Reservation” Pod can be viewed without trouble once the Gravity Forms plugin is disabled. It takes about 7 seconds to load. One more screenshot at the same link shows the table view on the “Manage Reservations” page (/wp-admin/admin.php?page=pods-manage-reservation):

    • 06 Reservations page

    The “Billing contact” column has been removed as per my test above, and for confidentiality. But when enabled, the page still loads in about 7 seconds.

    Once GravityForms is enabled, the problem returns and the “Manage Reservations” page times out.

    I am happy to provide credentials via email if you are open to the idea.

    Thanks again.

    Plugin Support Paul Clark

    (@pdclark)

    That is a bit puzzling, but it sounds like somewhere in Gravity Forms or perhaps the Gravity Forms Pods Integration, there may be a query which is attempting to get all users or content of another type. This could be various things, as even the database has memory and time limits of its own which vary by each installation.

    WP.org forum policies recommend avoiding sharing credentials. There are other Pods support venues on the plugin site, but here’s something that may point to what might be causing the issue on a test instance without anyone logging in:

    <?php
    /**
     * Plugin Name: Log Long Actions
     * Description: When active, write log files to <code>wp-content/uploads/action-logs/<code> which contain timestamped files of every action taking more than <code>0.5 seconds</code>. Also logs WPDB SQL queries nearby relevant actions.
     * Version: 1
     */
    
    class Log_Long_Actions {
    
      /**
       * In a default Pods + Gravity Forms install, 0.001 will log around 16 actions.
       * In a situation where something is awry or timing out, 0.5 might log a few.
       * In a default install, 0.5 will log nothing.
       */
      private $minimum_time_to_log = 0.5; // seconds.
      private $actions = [];
      private $counter = 0;
      private $log_dir = '';
      private $debug_backtrace_lookback = 10; // Maximum files to look back for where the action came from.
    
      private $actions_to_ignore = [
        // These actions will not be logged.
        // If the logging does not get to the action causing the timeout,
        // Add some actions associated with log files that do show up to skip them,
        // Then delete the logs and try again.
    
        'plugins_loaded',           // Starting here.
        'load_textdomain_mofile',
        'sanitize_file_name_chars',
        'mime_types',
        'sanitize_file_name',
        'attribute_escape',
        'posts_pre_query',
      ];
      private $action_patterns_to_ignore = [
        // Happens a lot in various forms.
        'gettext',
        'esc_',
        'clean_',
        'wp_kses',
      ];
      // Additionally do not log anything which is not in a file or directory containing 'gravity'.
      // This makes an assumption that we are looking in plugins/gravityforms/ or plugins/pods-gravity-forms/
      private $logged_action_file_path_must_contain = 'gravity';
    
      /**
       * Add a timer to the beginning and end of every action and filter.
       */
      public function __construct() {
        // If filters and ignores above are turned off,
        // This might take some memory!
        @ini_set( 'memory_limit', '4G' );
    
        /**
         * Define and possibly create a directory for logs in wp-content/uploads/action-logs.
         */
        $this->log_dir = sprintf( '%s/action-logs', wp_get_upload_dir()['basedir'] );
        if ( ! is_dir( $this->log_dir ) ) {
          wp_mkdir_p( $this->log_dir );
        }
    
        add_action( 'all', [ $this, 'action_start' ], PHP_INT_MIN );
        add_action( 'all', [ $this, 'action_end' ], PHP_INT_MAX );
    
        add_action( 'posts_pre_query', [ $this, 'posts_pre_query' ], PHP_INT_MAX, 2 );
      }
    
      private function maybe_ignore( $action = '' ) {
        foreach( $this->action_patterns_to_ignore as $nope ) {
          if ( false !== strpos( $action, $nope ) ) {
            return true;
          }
        }
        return ( in_array( $action, $this->actions_to_ignore ) );
      }
    
      /**
       * Note the most recent query in a log file prefix with a counter close to the most recent action.
       */
      public function posts_pre_query( $maybe_null, $wp_query ) {
        file_put_contents(
          sprintf(
            '%s/%s-query-%s.log',
            $this->log_dir,
            str_pad(
              (string) $counter,
              6,
              '0',
              STR_PAD_LEFT
            ),
            md5( $wp_query->request )
          ),
          (string) $wp_query->request
        );
        return $maybe_null;
      }
    
      public function action_start() {
        $this->counter++;
        $current_action = current_action();
    
        if ( $this->maybe_ignore( $current_action ) ) {
          return;
        }
    
        // Optional verbose PHP error log of current action.
        // error_log( $current_action );
    
        $counter                   = $this->counter;
        $start_time                = microtime( true );
        $this->actions[ $counter ] = $start_time;
        // Replacing DEBUG_BACKTRACE_IGNORE_ARGS with 0 or increasing $this->debug_backtrace_lookback will provide more information,
        // but will require more memory.
        $debug_backtrace           = debug_backtrace( DEBUG_BACKTRACE_IGNORE_ARGS, $this->debug_backtrace_lookback );
        $file_chain                = implode( ',', wp_list_pluck( $debug_backtrace, 'file' ) );
        $line_chain                = implode( ',', wp_list_pluck( $debug_backtrace, 'line' ) );
    
        // Optional very verbose PHP error log of current backtrace.
        // error_log( print_r( $debug_backtrace, true ) );
    
        // Save some time by only looking at Gravity Forms.
        // Commenting this out will write an enormous amount of files.
        if ( false === strpos( $file_chain, $this->logged_action_file_path_must_contain ) ) {
          return;
        }
    
        // Optional filtered verbose PHP error log of current backtrace.
        // error_log( print_r( $debug_backtrace, true ) );
    
        $file_path      = sprintf(
          '%s/%s-%s-at.%s.%s.log',
          $this->log_dir,
          str_pad(
            (string) $counter,
            6,
            '0',
            STR_PAD_LEFT
          ),
          str_replace( '/', '_slash_', $current_action ),
          (string) $start_time,
          md5( $file_chain . $line_chain . $_SERVER['REQUEST_URI'] )
        );
    
        file_put_contents(
          $file_path,
          sprintf(
            'Action "%s" from %s :%s%s',
            $current_action,
            $_SERVER['REQUEST_URI'],
            PHP_EOL . PHP_EOL,
            print_r( $debug_backtrace, true )
          )
        );
    
        unset( $debug_backtrace );
      }
    
      /**
       * Remove the log files if the action took less than 2 seconds.
       * 
       * This may not work perfectly if actions call themselves recursively or in similarly complex counting/timing situations.
       */
      public function action_end() {
        $current_action = current_action();
    
        if ( $this->maybe_ignore( $current_action ) ) {
          return;
        }
    
        $now = microtime( true );
    
        // For each log file associated with this action...
        foreach(
          glob( sprintf( '%s/*-%s-*.log', $this->log_dir, str_replace( '/', '_slash_', $current_action ) ) )
          as $log_file
        ) {
          // Get the counter from the file name.
          $counter = intval( explode( '-', basename( $log_file ) )[0] );
          $time_it_took = ( array_key_exists( $counter, $this->actions ) )
            ? ( $now - $this->actions[ $counter ] )
            : false;
    
          // Check if a start time still exists for that action call.
          if ( $time_it_took ) {
            // If it's been less than max seconds since the action started...
            if ( $this->minimum_time_to_log >= $time_it_took ) {
              // Delete the file.
              unlink( $log_file );
            }else {
              // Note how long it took.
              file_put_contents(
                $log_file,
                sprintf(
                  '%sTook %s seconds.',
                  PHP_EOL . PHP_EOL,
                  number_format( $time_it_took, 4 )
                ),
                FILE_APPEND
              );
            } 
          }
    
          // Clear the start time, as we have either removed the file or logged the execution time.
          unset( $this->actions[ $counter ] );
        }
    
        /**
         * The only remaining log files should be actions which either:
         *   - Took longer than the minimum time.
         *   - Did not complete due to timeout.
         */
      }
    }
    
    add_action(
      'plugins_loaded',
      function() {
        new Log_Long_Actions();
      }
    );

    The above plugin is a bit complex, as it is constructed in such a way that logs will be written for any filter or action in a file path containing gravity if it takes longer than 0.5 seconds to run all associated functions, or if it times out and fails completely.

    Completed actions/filters will log total run time if over the 0.5 setting. Actions/filters which fail to complete or timeout will still log a file saying what it was and where to find it, but will not contain a completion timer at the end.

    There are lots of comments in there are some optional verbose logs. I tested on Pods + Gravity Forms; it should log a file to wp-content/uploads/action-logs/xxx.log for any action or filter with gravity anywhere in the path.

    It can be installed as a plugin or mu-plugin… Don’t install it on production! It ended up being very efficient in testing, only taking 58 MB of memory, but removing any of the filters or ignores can result in much more memory and disk input/output being consumed.

    The idea is to load the plugin, then directly load the URL of the problematic page. Any long-running action or filter that does not complete within 0.5 seconds will show up in the log directory in uploads. They will be numbered in order of execution, and will contain a full execution path that led there, as well as the calling URL for cases such as background processes / AJAX calls.

    A critical look at the resulting files may have a good chance of leading to a file and line number in GF or GFPI very close to a point where a query is not completing.

    Edit: The above plugin is now marked Version: 1. In this revision, I added functionality similar to Query Monitor, in that all SQL queries going through WPDB will be logged in files prefixed by a counter associating it closely with related long-running actions. Unlike query monitor, it will not say how long the query took, but the last query to be logged will likely be the one too complex to complete, verifiable by either running it manually or considering its “weight” relative to the amount of content of various types found in the database.

    • This reply was modified 6 months, 2 weeks ago by Paul Clark. Reason: Add query log
    Thread Starter Awaken Solutions Inc.

    (@awakensolutions)

    Thank you so much for this. I added it as a regular plugin (zip here) and enabled it, along with the Pods and GravityForms plugins. I kept the “Pods Gravity Forms Add-On” plugin disabled initially.

    I then loaded the troublesome page (/wp-admin/admin.php?page=pods-manage-reservation) and got these files:

    000000-query-b8335edf83868e683ece87b81c7cf310.log

    			SELECT   wp_m1pvts9w5t_posts.*
    			FROM wp_m1pvts9w5t_posts 
    			WHERE 1=1  AND ( 
      0 = 1
    ) AND wp_m1pvts9w5t_posts.post_type = 'wp_global_styles' AND ((wp_m1pvts9w5t_posts.post_status = 'publish'))
    			GROUP BY wp_m1pvts9w5t_posts.ID
    			ORDER BY wp_m1pvts9w5t_posts.post_date DESC
    			LIMIT 0, 1

    000000-query-b28366afe46f00199c6ff0f037313092.log

    			SELECT   wp_m1pvts9w5t_posts.*
    			FROM wp_m1pvts9w5t_posts 
    			WHERE 1=1  AND ( 
      0 = 1
    ) AND wp_m1pvts9w5t_posts.post_type = 'wp_template_part' AND ((wp_m1pvts9w5t_posts.post_status = 'publish'))
    			GROUP BY wp_m1pvts9w5t_posts.ID
    			ORDER BY wp_m1pvts9w5t_posts.post_date DESC

    To be sure, I deleted those log files and reloaded the troublesome page and got the same thing with the new log files.

    And I also tried with the “Pods Gravity Forms Add-On” plugin enabled, but the log files were again the same.

    Thanks in advance for your thoughts and suggestions.

    Thread Starter Awaken Solutions Inc.

    (@awakensolutions)

    Hi Paul.

    While awaiting a reply on the above, to help further diagnose the issue, I deleted 200 reservations from the staging system. My thinking was that, since this bug is relatively recent, if it were related to the quantity of Reservations, or a buggy recent reservation, this would perhaps show that. I deleted the 50 oldest ones, and the 150 most recent ones.

    I did this from the WordPress UI by first disabling GravityForms to allow access to the Manage Reservations (/wp-admin/admin.php?page=pods-manage-reservation) page and deleting 25 at a time to get from 2884 to 2684.

    With that done, and re-enabling GravityForms, trying to access the Manage Reservations page worked very well, loading almost immediately.

    The fact that deleting 7% of the reservations made the Manage Reservations go from timing out to loading almost immediately suggests to me a possible bug with one of the reservations, rather than it just being less to load.

    I am restoring the WP Engine backup to get all the reservations back and will see if I can further diagnose if one specific Reservation is causing an issue, or what else it could be.

    Thread Starter Awaken Solutions Inc.

    (@awakensolutions)

    I’ve continued testing and am getting inconsistent results, possibly due to WP Engine object caching. Even the above workflow isn’t being consistent anymore.

    So, if you have any followup on the plugin you provided seemingly not giving us useful data, that might be the next best approach for us please.

    Thanks again.

    Thread Starter Awaken Solutions Inc.

    (@awakensolutions)

    I’ve done a bunch of combinations of enabled and disabled plugins and now.

    In one case the Manage Reservations page loaded fine (~5 sec) with all plugins enabled, except the Log Long Actions you provided. Once Log Long Actions is enabled, it took ~60 sec to load, sometimes working, sometimes timing out.

    But then clearing caches and trying different combinations gave different results.

    So nothing conclusive can be drawn about any specific plugin conflict anymore, and perhaps it is an issue with ressources being overused when trying to load the Manage Reservations page.

    To test the theory from your original reply, I deleted the User relationship field from my Reservations Pod. But the page still fails to load just as sporadically.

    I will await your feedback.

    Plugin Author Scott Kingsley Clark

    (@sc0ttkclark)

    @awakensolutions if you are still having trouble here, I’d like to offer you specialized support on this.

    Can you fill out the form at the bottom of this page and we can move forward with determining the root cause: https://docs.pods.io/pods-upgrade-troubleshooting-and-priority-support/

    Thread Starter Awaken Solutions Inc.

    (@awakensolutions)

    Thanks very much Scott. Done.

    Plugin Author Scott Kingsley Clark

    (@sc0ttkclark)

    I think we may have found a couple of areas that could be improved here but I’ll work with you via email there on the back-and-forth confirmations there. I’ll post an update here when it’s all done.

    Plugin Author Scott Kingsley Clark

    (@sc0ttkclark)

    After discussion and some dev work — we have everything resolved in Pods 3.2.1 for this.

Viewing 13 replies - 1 through 13 (of 13 total)
  • You must be logged in to reply to this topic.