This is similar to the following issues, yet new enough that I'm opening a new report:
The configured Mollom API keys are invalid
Invalid API Keys

This bug was supposed to have been fixed with the 7.x-2.1 release as referenced in the notes from this node: False-negative client/key validation status if check happens when Mollom service is down

However, I'm still experiencing the same problem. I've used Mollom for going on two years now, and never had this happened to me until I upgraded to version 7.x-2.0. Since then, it has happened almost every week, that the Mollom API keys will shift to an invalid status and my site gets flooded with spam until the keys revert to valid again. This is still happening even though I've now upgraded to 7.x-2.1. Yes, I've asked and my server can communicate with rest.mollom.com -- I do not have a way to check the server time myself, but I can ask if you think this might be a problem. My site is hosted by Drupal experts who contribute heavily to core, and I've never had a problem with this until immediately after the upgrade to 7.x-2.0, so I'm thinking it might be something else besides the server time being too far offset with world clocks. Here's my latest log message:

TYPE	mollom
DATE	Tuesday, June 19, 2012 - 23:10
USER	admin
LOCATION	http://fashionbelle.com/admin/config?render=overlay
REFERRER	http://fashionbelle.com/user/1
MESSAGE	Invalid API keys.
Error 401: Invalid authentication.

Request: POST http://rest.mollom.com/v1/site/31f7e1a1b384843df2e340f88ada861f
  platformName = 'Drupal'
  platformVersion = '7.14'
  clientName = 'Mollom'
  clientVersion = '7.x-2.1'
Request headers:
  Accept = 'application/xml, application/json;q=0.8, */*;q=0.5'
  Content-Type = 'application/x-www-form-urlencoded'
  Authorization = 'OAuth oauth_consumer_key="31f7e1a1b384843df2e340f88ada861f", oauth_version="1.0", oauth_nonce="82311fd19cc1dbafda746013bab2ce5c", oauth_timestamp="1340165412", oauth_signature_method="HMAC-SHA1", oauth_signature="zLuIGs7RmKayO8JxX2pLwzQ699g%3D"'
Invalid API keys.

SEVERITY	error
CommentFileSizeAuthor
#8 Pantallazo.png14.15 KBmar111
#2 mollom-api-keys.gif92.97 KBcouturier

Comments

sun’s picture

Hm. That's odd.

The previous issues you linked to were rather caused by the "opposite" - the module cached the bogus "invalid API keys" response and did not attempt to re-check its API keys when it should have.

You've already mentioned the server time, but it's not clear to me whether you actually confirmed that it is correct?

How often do you see those "invalid API keys" errors in your logs? (and how many times during the time-frame when the module did not talk to Mollom?)

In general, given that you actually see a log message containing an authorization error, this means that the module actually tries to communicate, but the API keys are reported as not valid for any reason.

couturier’s picture

StatusFileSize
new92.97 KB

I've sent an email to my hosting provider and will get back to you on the server time when I hear from him.

To give you an example of the string of reports I get when the API keys revert to invalid, let's take today's incident. I'm attaching a screenshot showing a sample of the number of log messages. The first indication of a problem seems to appear when I get a red "x" mark with some CAPTCHA function. Normally, when API keys validate, I think this works out okay with no red x. So, here's the first message today that showed a red x for retrieving a CAPTCHA:

TYPE	mollom
DATE	Tuesday, June 19, 2012 - 22:09
USER	Anonymous (not verified)
LOCATION	http://fashionbelle.com/node/add/forum/1/
REFERRER	http://fashionbelle.com/node/add/forum/1/
MESSAGE	Retrieved new CAPTCHA
Error 401: Invalid authentication.

Request: POST http://rest.mollom.com/v1/captcha
  type = 'image'
  ssl = 0
Request headers:
  Accept = 'application/xml, application/json;q=0.8, */*;q=0.5'
  Content-Type = 'application/x-www-form-urlencoded'
  Authorization = 'OAuth oauth_consumer_key="31f7e1a1b384843df2e340f88ada861f", oauth_version="1.0", oauth_nonce="8bb9def9dd40540d2bb355e77d1ed795", oauth_timestamp="1340161821", oauth_signature_method="HMAC-SHA1", oauth_signature="mE3py3qRAykXz6mANgUqwUbI93A%3D"'
Retrieved new CAPTCHA

SEVERITY	error

Then, after about a dozen messages identical to that one, the error switched to "Invalid API keys," with a new message that looks like this:

TYPE	mollom
DATE	Wednesday, June 20, 2012 - 01:11
USER	admin
LOCATION	http://fashionbelle.com/admin/reports/status?render=overlay
REFERRER	http://fashionbelle.com/user/1
MESSAGE	Invalid API keys.
Error 401: Invalid authentication.

Request: POST http://rest.mollom.com/v1/site/31f7e1a1b384843df2e340f88ada861f
  platformName = 'Drupal'
  platformVersion = '7.14'
  clientName = 'Mollom'
  clientVersion = '7.x-2.1'
Request headers:
  Accept = 'application/xml, application/json;q=0.8, */*;q=0.5'
  Content-Type = 'application/x-www-form-urlencoded'
  Authorization = 'OAuth oauth_consumer_key="31f7e1a1b384843df2e340f88ada861f", oauth_version="1.0", oauth_nonce="db1771e47229692267839351e468edb7", oauth_timestamp="1340172695", oauth_signature_method="HMAC-SHA1", oauth_signature="A7Nvv3bQ5BwRIOEHlIkKOxt%2Ff%2BY%3D"'
Invalid API keys.

SEVERITY	error

Normally, I don't look at the log, I just busily delete all the extra spam while the API keys are out of service and wait eagerly until they start working again. It usually takes a day or two, and this has been happening around once a week since my upgrade to 7.x-2.0, and continuing on now with similar frequency for 7.x-2.1. I never had a single problem with this prior to 7.x-2.0, and it started within just a few minutes of that upgrade, making me wonder if it had something to do with that upgrade.

. . . To follow up, the keys reverted back to valid the following morning. The next Mollom messages after the above listed showed me logging in as admin on 6-20-2012 at 9:05, deleting spam comments, and then a log message saying "The API keys are valid." This is a typical sequence of events. I would not be surprised if the Mollom keys revert to invalid over the coming weekend, since this seems to happen with more frequency on Fridays and Saturdays. It could be the weekend or it could be the fact that this spring I have generally done most of my website work on the weekends and have been logged in more often then. I'm still waiting to hear back about the server clock and will let you know.

sun’s picture

Meanwhile, I've double-checked the OAuth protocol parameters and generated signature, and it appears to be correct.

I've forwarded this issue to Mollom backend engineers, and one possible reason for this might be that your server time is synchronized, but it might drift relatively fast and is suddenly reset by the ntp daemon that synchronizes the time with world clocks/universal time.

couturier’s picture

Thanks, sun. Here's a copy of my IRC conversation on #drupal-oklahoma about the server clock.

[10:03] kvanderw: Wondering if the server clock is synchronized with world clocks? "sun" at d.o says that might be creating problems I've had this spring with Mollom API key validation, too far an offset of time on the server clock.
[10:34] couturier: I can actually answer that question. Its not synced, unfortunately. We do monitor it and try not to let it get more than 1 minute +/- though
[10:36] drakythe: Wow, so that might be my problem after all. What to do? My Mollom API keys have been reverting to invalid about once a week this spring, flooding my site with spam. Sun says it might be my server clock causing the invalidation. Thanks for your answer.
[10:38] couturier: I know we looked at syncing it at one point, but that sorta fell by the wayside due to other priorities :( -- if it's causing mollom issues though, its something that definitely needs to be looked at, I'll bring it up to kvanderw.
[10:39] drakythe: Would appreciate your bringing it up. At this point, we can't figure out anything else that might have been causing the problem. I figured since you guys host so many Drupal sites, you would have noticed it on your others, too. It all started with my upgrade to Mollom 7.x-2.0 and has continued through 2.1, so I thought it was due to the upgrade, but sun says probably not.
[10:42] couturier: Haven't had any other sites report an issue to us, but still something we need to look into. Thanks for the heads up.
[10:43] drakythe: Thanks, I'll keep working with sun and if we figure out any other thing that might be causing it, I'll let you know. As I said, I think it has to do with the 7.x-2.0 upgrades and beyond, since it started immediately after that and I'd never had a problem before.
[10:43] couturier: Yeah, that would make it seem like an upgrade issue.

sun’s picture

Category: bug » support
Status: Active » Fixed

Its not synced, unfortunately. We do monitor it and try not to let it get more than 1 minute +/- though

That pretty much hints at exactly what we've guessed. While a drift of multiple minutes within such short periods of time is very extreme and unusual (and generally hints at some other infrastructure/hardware/operating-system problems), it is perfectly possible, and provides the logical explanation for how the OAuth protocol parameters can become invalid and suddenly valid again.

That said, while discussing this further with the backend engineers, we concluded that we can improve the client-side implementation to automatically detect a too high time offset/deviation from universal time by parsing/evaluating the date in the HTTP response headers and comparing it to the local server time. If that offset gets too large, the module should log a more severe error message that precisely states the time offset problem. Created #1649326: Concise error messages in case the local server time is not synchronized with universal time to implement that.

couturier’s picture

Thank you so much, sun. I've notified my hosts of this problem. This will be very helpful to have a more precise error message as to what was going on. Strange, though, that I would have had zero problems with this for over a year on Mollom, then within minutes of upgrading to 7.x-2.0 and beyond, I've had dozens of incidents.

Status: Fixed » Closed (fixed)

Automatically closed -- issue fixed for 2 weeks with no activity.

mar111’s picture

StatusFileSize
new14.15 KB

I have exactly the same problem, after a couple of weeks longer recognize the API keys.

pwaterz’s picture

I had the same problem and went away after I ran

ntpdate ntp.ubuntu.com