In #210876: Add logging of who installs/uninstalls a module, I introduced some new logging for module changes. I would like to introduce more WATCHDOG_INFO and WATCHDOG_DEBUG level logging events for node and comment creation, edits, etc, but I think it might start looking ugly to be re-creating the assertLogMessage() function I used in the testing for module changes.

The attached patch uses the parameters of watchdog() to create an option for selecting the number of matching logs in the database. Then it replaces the assertLogMessage() function in the module changes tests for system.test with this new function.

Comments

boombatower’s picture

StatusFileSize
new6.03 KB

Seems fine, I would tweak it a bit.

drupalGetLogMessage() -> drupalGetLogMessages() since it can return more than one.

   * Verify a log entry was entered for a module's status change.
   * Called in the same way of the expected original watchdog() execution.

to (follow comment standard [1 line summary then blank line before details], and the method doesn't verify anything...)

   * Get the number of watchdog messages that match the parameters.
   *
   * The parameters are the same as those to watchdog(). In order to retrieve
   * the message count of a particular message use the exact same parameters.

added:

   * @return
   *   The number of watchdog messages that match the parameters.
   * @see watchdog()

Added protected scope modifier.

You could also make assertLogMessage() like previously exists and have it call drupalGetLogMessages(), not sure of all the intended uses.

deekayen’s picture

StatusFileSize
new6.04 KB

This fixes assertTrue output strings in system.test I missed with invalid replacement text.

dries’s picture

but I think it might start looking ugly to be re-creating the assertLogMessage() function I used in the testing for module changes.

I don't understand this part. How would the assert not be re-usable for comments and node logs? I'm not sure I understand the intend of this clean-up. Would you mind to explain that some more?

deekayen’s picture

assertLogMessage() as it is now is in system.test, in the ModuleTestCase class to be specific. If for example, I submitted a patch to comment.module to add a WATCHDOG_DEBUG for previewing comments, I'd have to test that the log entry was generated. Without a patch like this to simpletest, I'd have to then copy assertLogMessage() from ModuleTestCase in system.test to comment.test, probably into CommentHelperCase or re-arrange CommentHelperCase to extend something else that contained the copied assertLogMessage().

Moreover, given my general feelings about getting by with the minimum acceptable number of tests to get a patch accepted and move on to the next one, I assume watchdog entries are probably rarely tested throughout the rest of Drupal core and this could simplify that happening in other cases.

I'm only even doing this because it was apparently important to write tests for #210876: Add logging of who installs/uninstalls a module, which all it did was do logging. If it's not important to test watchdog entries, then those tests should be backed out. Otherwise, there are exactly ZERO instances of WATCHDOG_DEBUG entries in core and I intend, at least right now, to add some, which has the apparent prerequisite of testing them to get them accepted to core.

As far as #1, I have no certain preferences for function names to call this proposed addition. I just thought assertLogMessage() didn't fit quite as well in the group of other assert functions where something in the interface exists or doesn't, or a comparison of some sort was TRUE/FALSE. That said, I'm sure somehow it would come in handy if we are to proceed with testing watchdog entries' existence.

deekayen’s picture

I suppose I should also mention I'd prefer not to pursue this line of testing, back out the tests from #210876: Add logging of who installs/uninstalls a module, and count testDBLogAddAndClear in dblog.test as the functionality proof for watchdog being functional. If for some reason testDBLogAddAndClear isn't good enough to confirm the functionality of watchdog, then work on that instead of scattering evidence of this method around core.

dries’s picture

I'm not opposed to moving the function and making it globally available (that is a great thing) -- I was wondering why you moved the actual assert() out of that function. That doesn't seem to provide a demonstrable benefit.

deekayen’s picture

StatusFileSize
new9.06 KB

I moved it out because drupalGetMessages() counts log messages. Adding an assertTrue to the counting function wouldn't provide for cases where you want to test that an error or other message wasn't logged. An example is the assertTrue in drupalLogin(). For login_security in contrib I had to re-write drupalLogin() as drupalLoginLite() without the assertTrue on a successful login so I could make sure logins failed for blocked accounts.

This version renames drupalGetMessages() to drupalCountMessages() and then adds assertLogMessage() and assertNoLogMessage() and updates the tests in system.test to use the new assertLogMessage() function.

Since there are so many parameters to assertLogMessage(), would it be better to have the standard three parameters of [what to look for], $message, and $group by passing the watchdog parameters as a keyed array or object or is this way better to better mimic watchdog()?

boombatower’s picture

It would be nice if we could do the following:

$object = watchdog(...);
$this->assertLogMessage($object);

And have $object contain all the keys passed to watchdog, but then that begs the question...we are testing that watchdog() works. The test for watchdog() should be a test of its own and all other tests should assume it works. It may be fine just to count the number of watchdog statements since we ran some code.

More like:

$this->markWatchdogCount();

// Do stuff that will generate watchdog messages, in this example 2 messages.

$this->assertWatchdogCount(2);
deekayen’s picture

The test for watchdog() should be a test of its own and all other tests should assume it works.

That's kind of where I was taking my comment in #5. We have other tests to make sure watchdog() works. What this issue's proposed assert basically does is tell you if someone (re)moved the watchdog call you were expecting.

Instead of doing all this, is there some degree level of testing watchdog() through simpletest/tests/bootstrap.test, system.test, or dblog.test that then we wouldn't worry about it not working elsewhere?

If the desire really is to test to make sure the entry was made, I don't think we can just get away with counting an incremented watchdog row count, we should actually verify the text is relating to the watchdog entry we were expecting, not a watchdog entry from a different hook_alter or something.

boombatower’s picture

I suppose that just doing a count won't work.

I am leaning towards just making sure we have a comprehensive watchdog test and assuming it works everywhere else.

Status: Needs review » Needs work

The last submitted patch failed testing.

boombatower’s picture

sun’s picture

My patch complements this issue: #652394: Aggressive watchdog message assertion

boombatower’s picture

Status: Needs work » Closed (duplicate)

#13 was committed and seems to overlap this issue.