Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-63315

Cursor already declared DB errors with Postgres

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 3.5.1, 3.6.5, 3.7.1, 3.8
    • Fix Version/s: 3.6.6, 3.7.2
    • Component/s: Database SQL/XMLDB
    • Labels:
    • Testing Instructions:
      Hide
      1. Ensure that you are using Postgres database and the 'dbpersist' option is set to 'true' in your config.php.

        $CFG->dboptions = array(
        [... existing options ...]
        'dbpersist' => true,
        );
        

      2. Drop the attached file badcursor.php in the root of your moodle installation.
      3. Make requests to the file badcursor.php repeatedly (say 10 times in a row).
      4. EXPECTED: Each request should result in a PHP fatal memory error. And not to any Moodle exception with an error about failing to create cursors.
      Show
      Ensure that you are using Postgres database and the 'dbpersist' option is set to 'true' in your config.php. $CFG->dboptions = array( [... existing options ...] 'dbpersist' => true, ); Drop the attached file badcursor.php in the root of your moodle installation. Make requests to the file badcursor.php repeatedly (say 10 times in a row). EXPECTED: Each request should result in a PHP fatal memory error. And not to any Moodle exception with an error about failing to create cursors.
    • Workaround:
      Hide

      As a workaround I think you can turn off the fetch buffer in dboptions:

      $CFG->dboptions = array(
      [... existing options ...]
      'fetchbuffersize' => 0,
      );

      Show
      As a workaround I think you can turn off the fetch buffer in dboptions: $CFG->dboptions = array( [... existing options ...] 'fetchbuffersize' => 0, );
    • Affected Branches:
      MOODLE_35_STABLE, MOODLE_36_STABLE, MOODLE_37_STABLE, MOODLE_38_STABLE
    • Fixed Branches:
      MOODLE_36_STABLE, MOODLE_37_STABLE
    • Pull 3.6 Branch:
      MDL-63315-m36
    • Pull 3.7 Branch:
      MDL-63315-m37
    • Pull Master Branch:
      MDL-63315-master

      Description

      We are seeing an issue where we are getting page failures and DB errors on our Postgres setup.

      The PHP Log:

      [06-Sep-2018 13:21:30 America/Detroit] Default exception handler: Error reading from database Debug: ERROR:  cursor "crs5" already exists
      SELECT cc.id, COUNT(c.id) AS coursecount
                              FROM mdl_course_categories cc
                          LEFT JOIN mdl_course c ON c.category = cc.id
                                  WHERE cc.id IN ($1,$2)
                          GROUP BY cc.id
      [array (
        0 => '179',
        1 => '299',
      )]
      Error code: dmlreadexception
      * line 486 of /lib/dml/moodle_database.php: dml_read_exception thrown
      * line 248 of /lib/dml/pgsql_native_moodle_database.php: call to moodle_database->query_end()
      * line 764 of /lib/dml/pgsql_native_moodle_database.php: call to pgsql_native_moodle_database->query_end()
      * line 1560 of /lib/navigationlib.php: call to pgsql_native_moodle_database->get_recordset_sql()
      * line 1840 of /lib/navigationlib.php: call to global_navigation->load_all_courses()
      * line 2588 of /lib/navigationlib.php: call to global_navigation->load_all_categories()
      * line 1278 of /lib/navigationlib.php: call to global_navigation->add_course()
      * line 224 of /blocks/navigation/block_navigation.php: call to global_navigation->initialise()
      * line 166 of /blocks/navigation/block_navigation.php: call to block_navigation->get_navigation()
      * line 288 of /blocks/moodleblock.class.php: call to block_navigation->get_content()
      * line 230 of /blocks/moodleblock.class.php: call to block_base->formatted_contents()
      * line 1211 of /lib/blocklib.php: call to block_base->get_content_for_output()
      * line 1263 of /lib/blocklib.php: call to block_manager->create_block_contents()
      * line 604 of /lib/outputrenderers.php: call to block_manager->ensure_content_created()
      * line 39 of /theme/bootstrapbase/renderers/core_renderer.php: call to core_renderer->standard_head_html()
      * line 36 of /theme/ou_bs_base/layout/columns2.php: call to theme_bootstrapbase_core_renderer->standard_head_html()
      * line 1287 of /lib/outputrenderers.php: call to include()
      * line 1217 of /lib/outputrenderers.php: call to core_renderer->render_page_layout()
      * line 1881 of /lib/setuplib.php: call to core_renderer->header()
      * line 48 of /question/edit.php: call to bootstrap_renderer->__call()
      

      And the Postgres Log:

      2018-09-06 13:21:30.365 EDT [45862] ERROR:  cursor "crs5" already exists
      2018-09-06 13:21:30.365 EDT [45862] STATEMENT:  DECLARE crs5 NO SCROLL CURSOR WITH HOLD FOR SELECT cc.id, COUNT(c.id) AS coursecount
                                      FROM mdl_course_categories cc
                                  LEFT JOIN mdl_course c ON c.category = cc.id
                                          WHERE cc.id IN ($1,$2)
                                  GROUP BY cc.id
      

      Note that we do have dbpersist on, which may be causing this problem to show up, but that is a valid option, and we need it for performance reasons.

      What I think it happening is that there is code somewhere in our system that opens a recordset but doesn't close it (either because of bad code or an exception is thrown).

      Now in our particular case, it is always crs5, so I'm guessing we have code somewhat that is failing to close the 6th cursor opened for some reason, and I will work to track that down.

      But, I think the broader problem is still there. IMO, Moodle should be making sure that the cursor is closed, or checking if it exists.
      Personally, I think we should be adding recordset close to the shutdown handler just like we do for locks.

        Attachments

        1. badcursor.php
          0.3 kB
          Sam Marshall
        2. image-2019-09-04-08-55-13-679.png
          23 kB
          Janelle Barcega
        3. randomcursors.patch
          2 kB
          Sam Marshall

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                7 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Fix Release Date:
                  9/Sep/19

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 59 minutes
                  59m