Trigger watchdog when node rebuild permissions fails

I ran into this using og_access.module on a site migrated from D5 that has ~90,000 nodes. For completeness sake, here are the steps I've performed so far:

• Disable all contrib modules.
• Backed up the database.
• Switch to D6 branch in working copy.
• Move all modules out of sites/all/modules.
• Update.php - 62 updates.
• Backed up the database.
• Moved back cck & enable all modules. Ran all updates.
• Moved back filefield & enabled it. No applicable updates.
• Moved back imagefield & enabled it. Ran all updates.
• Moved back link & enabled it. Ran all updates.
• Moved back date & enabled it. Ran all updates. Had to run updates again to catch them all.
• Moved back token & enabled it. No applicable updates.
• Moved back imageapi & enabled it. No applicable updates.
• Moved back imagecache & enabled it. Ran all updates.
• Moved back javascript_aggregator & enabled it. Ran all updates.
• Moved back og & enabled it. Ran all updates.
• Rebuilt permissions. After completing it said "The content access permissions have not been properly rebuilt.".
• Disabled OG. Rebuilt permissions.
• Enabled OG. Rebuilt permissions

Each time I perform the Rebuild Permissions step it fails with the above error. I did a dump of the corresponding {batch} table record when it got to the 'finished' callback and it said the following:

Array
(
    [sets] => Array
        (
            [0] => Array
                (
                    [sandbox] => Array
                        (
                            [progress] => 96600
                            [current_node] => 4605
                            [max] => 96553
                        )
                    [results] => Array
                        (
                        )
                    [success] => 
                    [title] => Rebuilding content access permissions
                    [operations] => Array
                        (
                            [0] => Array
                                (
                                    [0] => _node_access_rebuild_batch_operation
                                    [1] => Array
                                        (
                                        )
                                )
                        )
                    [finished] => _node_access_rebuild_batch_finished
                    [init_message] => Initializing.
                    [progress_message] => Remaining @remaining of @total.
                    [error_message] => An error has occurred.
                    [total] => 1
                )
        )
// and more with the form details..

Tracing through the code I found that _node_access_rebuild_batch_operation() was doing all of the work of managing the batch process, which contains the following:

  $result = db_query_range("SELECT nid FROM {node} WHERE nid > %d ORDER BY nid ASC", $context['sandbox']['current_node'], 0, $limit);
  while ($row = db_fetch_array($result)) {
    $loaded_node = node_load($row['nid'], NULL, TRUE);
    // To preserve database integrity, only aquire grants if the node
    // loads successfully.
    if (!empty($loaded_node)) {
      node_access_acquire_grants($loaded_node);
    }
    $context['sandbox']['progress']++;
    $context['sandbox']['current_node'] = $loaded_node->nid;
  }

The part that seemed confusing to me was the following line:

    $context['sandbox']['current_node'] = $loaded_node->nid;

I figured that there could be circumstances when the $loaded_node would fail on the last node load of a particular loop thus storing an empty value in $current_node for the next loop. On the next loop the database abstraction layer takes this NULL value and the query above, performs a type casting on the NULL to make it an integer, resulting in the following query:

SELECT nid FROM {node} WHERE nid > 0 ORDER BY nid ASC

This could then cause the whole batch process to start over.

In my case it always ran to completion and returned the error above.

What I did to fix it was changed the current_node assignment to just use the nid value from the row itself, i.e.:

    $context['sandbox']['current_node'] = $row['nid'];

That allowed it to successfully complete the task.

subscribing.

subscribing

This seems quite logical. If we are setting ['progress'] to be some property of an invalid (empty?) object, something is clearly amiss =)

In my case, it fixed a recurring problem in a site with 30k nodes which has both Workflow Access and OG Access modules enabled. (Before, after finishing the rebuild it still informed me that they should be rebuilt).

Just a change: patch contains some cruft:

diff -u -p -r1.36 cron.php
--- cron.php	9 Aug 2006 07:42:55 -0000	1.36
+++ cron.php	8 Nov 2009 20:48:48 -0000
@@ -8,4 +8,6 @@
 include_once './includes/bootstrap.inc';
 drupal_bootstrap(DRUPAL_BOOTSTRAP_FULL);
-drupal_cron_run();
+// drupal_cron_run();
+print("<pre>");
+print_r(node_get_types());

I think the above should be removed. After that I think it's ready to go.

BTW I think this might also be a problem in D7? Here's a snippet from D7's _node_access_rebuild_batch_operation():

  // Process the next 20 nodes.
  $limit = 20;
  $nids = db_query_range("SELECT nid FROM {node} WHERE nid > :nid ORDER BY nid ASC", 0, $limit, array(':nid' => $context['sandbox']['current_node']))->fetchCol();
  $nodes = node_load_multiple($nids, array(), TRUE);
  foreach ($nodes as $node) {
    // To preserve database integrity, only acquire grants if the node
    // loads successfully.
    if (!empty($node)) {
      node_access_acquire_grants($node);
    }
    $context['sandbox']['progress']++;
    $context['sandbox']['current_node'] = $node->nid;
  }

If so we should attract some attention to this =)

I am very close to mark this as wont fix. How can the nid of a loaded node be 0 / NULL? You are fixing a symptom not the cause.

Same problem here. For example, in node_load():

SELECT * FROM node n INNER JOIN {users} u ON u.uid = n.uid INNER JOIN node_revisions r ON r.vid = n.vid WHERE n.nid=817

returns empty, but

SELECT * FROM node n INNER JOIN node_revisions r ON r.vid = n.vid WHERE n.nid=817

returns one row. These rows were of type 'uprofile', so it seems the advanced_profile_kit module didn't delete the profile node when the user account was deleted.

Please add the patch for the next D6 release.

@chx: re #6, is it possible that a node_delete could occur while a batch is processing, therefore causing node_load($nid) to not return a valid object? Are there any other possible cases? (My guess is YES, due to bad modules, database table corruption, cosmic rays, etc... of course, unlikely ... but possible.)

IMO if this patch makes Drupal more bulletproof... even if just by a tiny bit [EDIT: I missed saying "it's worth implementing" here] =)

And, OK, maybe it's not a "bug" as such. =)

You might try commenting out the

node_access_acquire_grants($loaded_node);

line. That should allow the batch process to run much faster and still attempt to load each node. Does that run to completion?

WARNING:
Running the rebuild after commenting out that line only fakes rebuilding permissions —
if it 'succeeds,' then Drupal will stop asking to rebuild permissions, but you haven't actually done it!

This is intended only as an intermediate step in finding the cause of the problem, by checking whether you can at least load all nodes. It will probably result in all nodes becoming inaccessible to all but administrative users!

I agree with chx that this is only making the problem. The real problem is that node_load() failed, and thus the node's access grants rebuild was not executed, so it gets flagged as a failure.

But that said, it's all but impossible to figure out what the root cause of the error was when such a thing occurs. I encountered the issue "somewhere" in my 60K nodes website, and only managed to track down the problem thanks to this issue providing a hint, and then tossing in some debug code (see #281326-51: The content access permissions need to be rebuilt.).

At the very least it seems like we ought to fire a dsm() and/or a watchdog when this condition happens:

    if (!empty($node)) {
      node_access_acquire_grants($node);
    }
    else {
      // OMG. PEOPLE ARE DYING.
    }

Since the issue exists in D7 too, bumping to 7.x-dev so we can fix it there first.

Turns out that technically, this is a duplicate of #315302: Node Access Rebuild never finishes (infinite loop) since that one is older. It's also been marked RTBC, pending tests. So I'm going to hijack this one and make it about error trapping instead. ;)

Just an FYI that this is similar to #225864: Don't assume that node_load returns a node ... I'm wondering if node_load itself should handle the watchdog entries to mitigate other possible occurrences. This won't stop the error messages but would at least give admins the ability to debug their problematic data.

This patch logs to watchdog inside node_access_rebuild().

I think the root problem is bad data being passed to node_load and that issues like this one are a symptom of the cause. I don't believe Drupal should have to account for bad data that has been entered but I do believe that we should at least notify admins of the root problem. I'm of the opinion that the only place this can happen is in node_load() ... otherwise you would have to write a patch to fix every instance of a module that uses node_load and assumes the node is proper.

For the sake of argument here's a quick patch that modifies node_load()

Here's one that corrects the typo in my last patch

Gah! Bad format in #13; sorry. retesting.

I re-rolled the patch I was working on it's original issue #225864: Don't assume that node_load returns a node

Possibly related: http://robshouse.net/blog-post/when-node-load-wont-load-and-anonymous-us...

#1: drupal-n471080.patch queued for re-testing.

#18: 471080-12-watchdog_in_node_access_rebuild.patch queued for re-testing.

Hello again, dear bug =)

Updating this to the node system and it needs to be rerolled for 8.0.

Still looks valid in node_access_rebuild(), adding a log message seems OK.

Not sure if this is the expected message, but please review, also is it applicable for 9.3.x?

Sorry, patch 37 was sent by accident. Please dot not consider, patch #36 is the one to be reviewd.

Sending patch without whitespace.

The patch #38 is applied successfully on version 9.4.x . Added a screenshot of patch.

Applied patch #38 successfully on drupal version 9.4.x
Thank you.

This issue is being reviewed by the kind folks in Slack, #needs-review-queue-initiative. We are working to keep the size of Needs Review queue [2700+ issues] to around 400 (1 month or less), following Review a patch or merge request as a guide.

Did not review or test

Moving to NW for the issue summary update requested in #34

This is a task now that #315302: Node Access Rebuild never finishes (infinite loop) is dealing with the actual bug.

This issue was originally created because when the node wasn't loaded, the batch failed and the user was presented with "could not be rebuilt" and "need to be rebuilt" messages simultaneously.

Now that #315302: Node Access Rebuild never finishes (infinite loop) fixed the bug when a node couldn't be loaded, I'm not really sure what relevant information we could provide in this log message and why it would be the job of this batch process to call out a faulty node? A node has to exist in the database and then produce an error on load to even hit this issue (since $nids come from an entity query).

What information could we actually provide here that would help a user in any way? They'd still see a successful batch operation afaict.

@acbramley where would that info popup though? Way I read this one was just adding a logger to the batch

@acbramley where would that info popup though?

My point in #50 is that there's not really any helpful info to add anyway. I'm not sure what you're referring to about an info popup.

I am removing the 'Novice' tag because what task someone new to Drupal contribution is not clearly defined. Converting to an MR would be but the subsystem maintainer is questioning the need for this change.