Node comment statistics are only partially exposed in node_load() and are missing last_comment_uid

I was about to open an issue for this but luckily found this one. There is indeed quite some discrimination in comment_node_load(): why exposing last_comment_name and not last_comment_uid, last_comment_name is empty for registered users and only useful for anonymous users. This make this comment_node_load() absolutely useless for other modules which want to display information on the last comment, these modules will need to implement their own custom database call. Note that there should be zero performance impact since the data is right there in the same denormalized record.

I'd be happy to write some test for this if it has any chance to go in D7 still.

This make this comment_node_load() absolutely useless for other modules which want to display information on the last comment, these modules will need to implement their own custom database call.

Proof is: forum.module implements its own db queries to extract the last_comment_uid data.

seems reasonable

Can we update forum module too then?

Agreed with catch in #4. Let's take advantage of it then.

I've looked at forum.module into more details but the occurrences of last_comment_uid don't appear within the scope of node_load(), so please disregard what I said in #2. We're back at #1 and to follow up on Moshe's RTBC, I've added a fair amount of tests for node comment statistics which are not tested anywhere else in core.

Wow, nice tests. RTBC unless bot says no.

Committed to CVS HEAD. Thanks.

There must be something "chancy" about the tests because since this was committed, they fail randomly. http://qa.drupal.org/head-status shows 3 fails:

* The value of node last_comment_timestamp is the comment #1 created date.
* The value of node last_comment_timestamp is still the comment #1 created date.
* The value of node last_comment_timestamp is the comment #3 created date.

When re-testing other patches, sometimes 2 of these fails show, sometimes none. Something's amiss.

I've run these tests a few times locally without failures. I'm uploading a debug patch here which will display the timestamps (as well as some var_export() calls which I use locally).

@scor: I'm doing the same thing locally, I got 1 failure (2 assertions) out of 10 or so tries, unfortunately I didn't catch the actual timestamps.

@scor, if the only way to resolve this is to actually run it on a testbot after getting it committed, you'll have to use debug() instead of $this->verbose(), as debug() gets reported back, verbose doesn't.

I got one of the suckers locally:

* The value of node last_comment_timestamp is the comment #3 created date. (comment.test line 485)

last comment timestamp:
'1289165122'
comment created:
'1289165123'

I peppered comment.test with sleep(2) calls to try to expose a problem. I'm still not quite sure what causes this, since the difference is 1, not 2.

Also, the first time I reproduced it was the first 2 assertions in #9, whereas the second reproduce it was only the third assertion. Quite strange.

Since the bot is now back up, retitling.

This is still critical because it's leading to false failures in other issues, and with every new commit HEAD has a ~ 10% chance of breaking again. I suspect an actual problem in how $node->last_comment_timestamp is getting set, and the test is assuming that if the timestamp matches it was set correctly (this could just be due to the test running in < 1 second).

I've looked into the code and I have spotted a few things that are a little fishy. Since I'm new to Drupal and PHP, please excuse me if I do not use your lingo and may sound a little verbose.

All file and line references are to current HEAD, no patch applied.

In function comment_save, when creating a new comment, there's a call to db_ignore_slave (in file comment.module line 1540). But there's nothing like that when just updating the comment (would be somewhere around line 1453).

However that should not be the problem we have here because the tests (at least the ones that fail) are only creating comments and not modifying them.

There are several inconsistencies in where the data for node->last_comment_timestamp comes from.

The initial value when creating a node (no comments yet) comes from node->changed (line 1266 of comment.module) however the test compares the initial value with node->created (comment.test line 412). This currently does not fail, but it depends on nodes being created with identical values for those fields (something that belongs to the node interface. It may or may not be part of that interface contract, I'm not sure.)

Another consequence of that is that there is also a difference when loading a node with comments enabled but with no comments (last_comment_timestamp comes from the statistics and, as seen, will be the value node->changed had during node creation) and when loading a node with comments disabled, because in this latter case the source is node->created (see line 1226).

Maybe line 1266 should in fact use node->created.

When adding or modifying a comment, _comment_update_node_statistics is called and last_comment_timestamp becomes last_comment->changed (where last_comment is whatever comment was posted last for that node). However the test compares this with comment->created (comment.test lines 426, 452, 474).

Interestingly these are exactly where we have the test failing (and in a non-deterministic way).

The reason is, of course, that comment->created and comment->changed are not always equal. Not even when the comment is being created. In fact they come from two different sources as you can see in the code that assigns them (lines 2111, 2112 of comment.module) in function comment_submit.

The non-determinism when creating a new comment is due to the little delay between REQUEST_TIME and when line 2111 is executed to interpret the 'now' value from line 2108 when, eventually, time has 'ticked' to the next second (which explains why carlos8f in #13 only saw a difference of 1).

This patch should fix the tests and make them consistent with the code.
When the last_comment_timestamp comes from an actual comment, it's always the last comment changed timestamp, both in code and in tests.

Also it fixes the inconsistency with nodes that have no comment: in all cases (comments enabled but no published comment yet or comments disabled) the last_comment_timestamp is the node created timestamp, both in code and in tests.

Note that the tests that were failing are now totally oblivious to whether created and changed are supposed to be identical on creation. As far as the test is concerned either or both nodes and comments can be created with those fields having differring values (and the same for any other thing that has both created and changed fields).

Someone would consider it a problem if they are not identical. Personally I do not care. It is just a question of what is the "contract" of these interfaces. I think that if it's not expressly promised somewhere that they are identical, nobody should assume that they are. Also nobody should assume that created <= changed, unless that's an explicit contract.

Of course it's not me but the Drupal community that shall decide what is a contract here and what is not.

In any case, currently, in the case of comments it may be that created = changed + 1

And fixing that may be beyond my current PHP capabilities.

P.S.: and I totally ignored the db_ignore_slave() question because I'm not sure what that really is. I know from the code that it makes the session use the database differently. Probably forcing it to use only the master. But I have no idea what kind of master-slaves or masters-slaves setups it's supposed to deal with nor I have a clue on how the DB stuff works in Drupal.

Also it fixes the inconsistency with nodes that have no comment: in all cases (comments enabled but no published comment yet or comments disabled) the last_comment_timestamp is the node created timestamp, both in code and in tests.

While this behaviour in HEAD is semantically wrong, it's by design. Modules like tracker use the 'last_comment_timestamp' to actually mean 'last_comment_timestamp, or updated if there's no comments'. This has been a candidate for refactoring since 2007, and while some of the performance issues from the current schema were dealt with in Drupal 7, the overall issue of the normalized table anith d special casing is still there, this issue has some more background if you're interested #148849: Refactor {comment_entity_statistics} into performant Field.

With that in mind I think the node->changed behaviour should stay.

On db_ignore_slave(), the idea is that if you post a new comment (which can happen via anonymous users), you should immediately see that comment - so if a site is using read-only slaves and loading comments from those, then that behaviour would be disabled for the person posting the comment - they'd hit the master for read queries for that time period. Not doing this for updates looks like an oversight to me.

Rollback patch to revert the tests hunk and get the test bot process going again.

Marking as needs review, if we commit this we can go back to fixing the tests without the bot going haywire in the meantime.

Modules like tracker use the 'last_comment_timestamp' to actually mean 'last_comment_timestamp, or updated if there's no comments'.

That's the best prove that my concern about the actual "contract" behind the interfaces is not just a pet peeve of mines.

This new patch leaves that part alone.

I'm adding in the db_ignore_slave() call according to:

On db_ignore_slave(), the idea is that if you post a new comment (which can happen via anonymous users), you should immediately see that comment - so if a site is using read-only slaves and loading comments from those, then that behaviour would be disabled for the person posting the comment - they'd hit the master for read queries for that time period. Not doing this for updates looks like an oversight to me.

Rollback patch to revert the tests hunk and get the test bot process going again.

There's no need to give up testing. I'm leaving the tests in with the amendments needed to have them test what the code does (and is supposed to do).

This patch should fix the testing problems that we currently have.

There are IMO only two details that may need discussion (and eventually fixing). But maybe these should be another issue (probably a 'task' more than a bug, correct me if I'm wrong)

The two details are:

1) There is a little logic inconsistency in the fact that when a node is created the last_comment_timestamp field in the node_comment_statistics table comes from node->changed (regardless of whether comments are enabled for that node) however when the node is loaded (if I understand Drupal logic correctly comment_node_load() is called ad a hook from node_load(). See, I'm learning your lingo!) the value is NOT read from the database and it is initialized from node->created. This means that, for nodes where node->comment is COMMENT_NODE_HIDDEN, the loaded value in the $nodes array is not the same value that is in the database. I assume that tracker is hitting the DB directly instead of reading the values from a node loaded with node_load(). However this inconsistency, for the moment, does not break the tests, so I'm leaving it in. (note: maybe we should add a test that breaks if we get to fix this inconsistency)

A possible fix for this would be to change line comment_node_load() to set the value from the DB regardless or to initialize it as node->changed. I could do that, but have no idea how to write a test that breaks if this becomes a regression. However, again: would this break some hidden contract?

2) There may (or may not) be an inconsistency in the fact that, upon creation, comment->changed and comment->created can be different, and changed be earlier than created. But this has not been a problem so far and again I'm not changing it.

tl;dr: The only change in code is the addition of the call to db_ignore_slave() for the codepath for a comment update. This is unrelated to this issue but should not break anything. The tests have been fixed: they now test what the code does instead of testing what they, wrongly, assumed it was doing. Therefore they should not break any more.

On IRC, yesterday, carlos8f raised a concern about not only forcing the test to succeed when the code is correct, but also forcing it to fail (deterministically) if the code becomes wrong.

This is a valid concern.

The attached patch addresses this problem and is therefore better than the earlier one.

+++ modules/comment/comment.test	8 Nov 2010 12:09:09 -0000
@@ -414,6 +414,11 @@ class CommentInterfaceTest extends Comme
+    // As we will compare timestamps with 1s granularity, to avoid ¶

+++ modules/comment/comment.test	8 Nov 2010 12:09:09 -0000
@@ -440,6 +445,11 @@ class CommentInterfaceTest extends Comme
+    // As we will compare timestamps with 1s granularity, to avoid ¶

+++ modules/comment/comment.test	8 Nov 2010 12:09:09 -0000
@@ -463,6 +473,11 @@ class CommentInterfaceTest extends Comme
+    // As we will compare timestamps with 1s granularity, to avoid ¶

trailing whitespace

+++ modules/comment/comment.test	8 Nov 2010 12:09:09 -0000
@@ -414,6 +414,11 @@ class CommentInterfaceTest extends Comme
+    sleep(1);

+++ modules/comment/comment.test	8 Nov 2010 12:09:09 -0000
@@ -440,6 +445,11 @@ class CommentInterfaceTest extends Comme
+    sleep(1);

+++ modules/comment/comment.test	8 Nov 2010 12:09:09 -0000
@@ -463,6 +473,11 @@ class CommentInterfaceTest extends Comme
+    sleep(1);

why not just +/-1 to timestamp of comment and do not slow down the whole test suit

Powered by Dreditor with Chrome support.

trailing whitespace

Sorry. This fixes those.

why not just +/-1 to timestamp of comment and do not slow down the whole test suit

How would the test change those?

Also I think that we are actually testing exactly the code that manipulates them, therefore any trick to force them to a different value would make the testing itself moot.

It's unfortunate that the test suite is delayed by 3 seconds because of this. In fact that's the objection I also raised to carlos8f in IRC. His answer was that this is ok if it's needed, and has been done already in other tests.

Not trying to be an ass, but the migrate module creates 5000 nodes in a second. Its pretty lame that that our tests routinely take seconds just sleeping.

I agree with Moshe. However sleep() does not take CPU time, so while it's true that tests might take a few more seconds to run, testbots generally run tests with a concurrency of 8 (other tests can run in the meantime). HEAD currently has a sleep() total equivalent to sleep(12).

+++ modules/comment/comment.module	8 Nov 2010 12:09:09 -0000
@@ -1451,6 +1451,10 @@ function comment_save($comment) {
+      // Ignore slave server temporarily to give time for the
+      // saved node to be propagated to the slave.
+      db_ignore_slave();

What does this have to do with this issue? How does it help to fix the broken tests? Do we have tests to make sure nothing breaks with the addition of db_ignore_slave()?

We have no PIFR testing environment that even comes close to testing db master/slave, of course, whether or not there are tests.

Ok. Moving out the db_ignore_slave() call.

This patch only fixes the test suite that is currently breaking the bot.

and now db_ignore_slave() has its own issue: #965628: db_ignore_slave() not called when saving a comment

+++ modules/comment/comment.test	8 Nov 2010 12:09:09 -0000
@@ -414,6 +414,11 @@ class CommentInterfaceTest extends Comme
+    // non-deterministic false-positives we mush ensure that they

s/mush/must

let me suggest a rewording of that sentence:

As we will compare timestamps with 1s granularity, we must ensure that they actually differ in order to avoid non-deterministic false-positives.

Powered by Dreditor.

There, amended as suggested in #31

We've basically designed our suite to be so slow that only a bot is willing to run it. People running even parts of the suite is unusual. I'd venture to say that there re less than a dozen people who regularly run the test suite with concurrency.

@moshe: what alternative to sleep() do you suggest to test time dependent functionalities?

Reverting the changes to the test (#32) except the sleep() calls, I am still unable to reliably reproduce a failure. In other words, the sleep() is not really doing anything. Since according to @catch the code in comment.module is working as intended, and the problem is just with the test, we should:

1. Revert the tests (#19)
2. Demote the issue to normal
3. Commit the tests once we can make them pass/fail 100% rather than being left to chance.
4. Profit

Here's a patch to revert just the comment timestamp tests until they can be worked out properly.

Let's commit this one to avoid false testbot failures and work on #965796: Add deterministic tests for last_comment_timestamp in a separate issue.

The patch in #36 is removing the failing tests. This is totally unneeded and a nonsense because we know how to fix the tests already.

I'm attaching a patch that fixes the current test failures, instead of removing them, and nothing more, ok?

@AnalogFile: if the test runs in < 1 second, all the timestamps are equal anyway and the assertions are nonsensical. If you'd like to fix the tests, please follow up in #965796: Add deterministic tests for last_comment_timestamp, and make sure you can produce a reliable failure so that the pass means something.

Re-attaching the RTBC patch.

Hm. I'm a bit torn. I hate removing tests from the test suite. OTOH, I really hate wasting contributors' time.

It sounds like this issue is tricky enough that it could benefit from its own dedicated issue (which looks like it's #965796: Add deterministic tests for last_comment_timestamp) to work out the exact test cases we want here.

So, committed #36 to HEAD to stem the bleeding for now.

if test runs in < 1 second, all the timestamps are equal anyway and the assertions are nonsensical.

That's exactly why the calls to sleep() are supposed to be in there. Note, however, that the tests (as patched by me) would have been valid even without those calls. Removing them was not a good idea.

In this issue, as it was reopened, the problem was that the tests were failing when they shouldn't have failed because the module code was correct. I call these false negatives. The patch in #38 would have fixed that without removing the tests.

make sure you can produce a reliable failure so that the pass means something.

The test is supposed to pass if the mainline code is correct and to fail if it is not correct. Presence or absence of the calls to sleep() would never make the test fail. They do not fix a case of false negative where the test can fail even if the code is correct.

They do the opposite: they fix a scenario where you could have false positives. In other words they make the test do what it is supposed to do: fail if the mainline code is wrong. I cannot produce a reliable failure without actually making the mainline code wrong. And that's not even something we should do. Writing code that does that means we are writing a test suite to test the testing code. In some situations this is in fact desirable (I know at least one person that have developed code that does exactly that. ADA code that checks the test suite used to validate the weapon control software of a military helicopter). But here we are not supposed to write anything at all (test or code) for the purpose of verifying the tests themselves.

The patch in #36 simply removes the tests altogether. It does not introduce sleep() delays. It does not test. The test suite will pass no matter what happens to the mainline code. The test suite passes if the mainline code is correct (as now) but it also passes if the mainline code becomes broken in the future.

The patch in #38 fixes the broken tests. It does not introduce sleep() delays. It does test something, but it does not test it all. The test suite passes if the mainline code is correct (as now) and it may fail if the mainline code becomes broken in the future, unfortunately it may also pass even if the mainline code becomes broken.

The patch in #32 is the best one, from the testing point of view. However it does introduce calls to sleep(). It does more testing than #38. The test suite passes if the mainline code is correct (as now) and it fails if the mainline code becomes broken in the future.

@AnalogFile we are all on volunteer time here. Our first (critical) priority is keeping the test bot healthy so the community can get relevant test results from their patches. We do appreciate your work on this. We just need to ensure that if we include these assertions, we are absolutely sure they will pass 100% of the time (i.e., chance is not involved). I am not absolutely sure that is the case for #32, which is why we needed to settle for a stop-gap so the other thousands of issues can have their patches tested unfettered. Please post in #965796: Add deterministic tests for last_comment_timestamp for further discussion/patches, thanks.