After creating a new node, I sometimes get a pause on the server and 2 errors are reported in the server logs:

Jan  2 13:58:06 piperhosting drupal: http://kpbj.com|1262469486|php|66.249.67.141|http://kpbj.com/people/2010-01-02/bonney_joins_pacific_asset_management||0||Duplicate entry '206dff69e98600c7b77b822e5f19ec83' for key 1 query: INSERT INTO boost_cache (hash, hash_url, filename, expire, lifetime, push, page_callback, page_type, timer, timer_average, base_dir, page_id, extension, url) VALUES ('206dff69e98600c7b77b822e5f19ec83', '9d0893c68f36dfc0acf5c843d5b83f61', 'cache/normal/kpbj.com/people/2010-01-02/bonney_joins_pacific_asset_management_.html', 1262470068, -1, -1, 'node', 'story', 17313, 17313, 'cache/normal/kpbj.com', '15589', '.html', 'http://kpbj.com/people/2010-01-02/bonney_joins_pacific_asset_management') in /usr/local/apache2/vhosts/kpbj.com/htdocs/sites/all/modules/boost/boost.module on line 2428.

Jan  2 13:58:06 piperhosting drupal: http://kpbj.com|1262469486|php|174.129.27.223|http://kpbj.com/people/2010-01-02/bonney_joins_pacific_asset_management||0||Duplicate entry '206dff69e98600c7b77b822e5f19ec83' for key 1 query: INSERT INTO boost_cache (hash, hash_url, filename, expire, lifetime, push, page_callback, page_type, timer, timer_average, base_dir, page_id, extension, url) VALUES ('206dff69e98600c7b77b822e5f19ec83', '9d0893c68f36dfc0acf5c843d5b83f61', 'cache/normal/kpbj.com/people/2010-01-02/bonney_joins_pacific_asset_management_.html', 1262470067, -1, -1, 'node', 'story', 18312, 18312, 'cache/normal/kpbj.com', '15589', '.html', 'http://kpbj.com/people/2010-01-02/bonney_joins_pacific_asset_management') in /usr/local/apache2/vhosts/kpbj.com/htdocs/sites/all/modules/boost/boost.module on line 2428.

The SQL server goes into "MySQL server has gone away" for about 15 seconds, then seems to recover and be back.

Comments

mikeytown2’s picture

Error could be the result of a MD5 collision; or multiple people hitting the same story with a slow MySQL Server.

The function that is causing the error:

function boost_put_db($filename, $expire, $lifetime, $push, $router_item, $timer, $timer_average, $extension) {
  global $base_root;
  $url = $base_root . request_uri();
  $hash = md5($filename);
  $hash_url = md5($url);
  db_query("UPDATE {boost_cache} SET expire = %d, lifetime = %d, push = %d, page_callback = '%s', page_type = '%s', timer = %d, timer_average = %d, base_dir = '%s', page_id = '%s', extension = '%s', url = '%s', filename = '%s', hash_url = '%s' WHERE hash = '%s'", $expire, $lifetime, $push, $router_item['page_callback'], $router_item['page_type'], $timer, $timer_average, BOOST_FILE_PATH, $router_item['page_id'], $extension, $url, $filename, $hash_url, $hash);
  if (!db_affected_rows()) {
    db_query("INSERT INTO {boost_cache} (hash, hash_url, filename, expire, lifetime, push, page_callback, page_type, timer, timer_average, base_dir, page_id, extension, url) VALUES ('%s', '%s', '%s', %d, %d, %d, '%s', '%s', %d, %d, '%s', '%s', '%s', '%s')", $hash, $hash_url, $filename, $expire, $lifetime, $push, $router_item['page_callback'], $router_item['page_type'], $timer, $timer_average, BOOST_FILE_PATH, $router_item['page_id'], $extension, $url);
  }
}

This only gets called when a page has been cached. Thus as a logged in user it can't directly happen (this error is not a direct result of a node being created). If you have something that is hitting the node right after it is created then having this error show up right after a node is created makes since. This has to do with the standard way of doing things in drupal not being 100% atomic. The Duplicate entry for key 1 query simply means that already exists in the database, thus if this errors out no big deal; entry is already in the database. I could/should put a @ in the front of the db_query() call to hide any error that might happen, due to multiple requests hitting it.

In terms of the "MySQL server has gone away" error if a node gets hammered right after it's creation and fills up all available MySQL connections this makes since; but we are talking about somewhere around 100 connections in under 15 seconds to that newly created node... odds of that happening are fairly low; and if 1 uncached page brings your site down you might want to look into getting a faster hosting solution. If you have any other info in regards to this error, that would be nice to know.

mikeytown2’s picture

Title: PHP Errors when creating nodes » boost_put_db should not throw Duplicate entry error; happens when un-cached node get hammered.
gregarios’s picture

Nothing accessed the page 2 seconds after I created it, except myself. No accesses were registered in the access log for that time period at all.

mikeytown2’s picture

are you using any kind of rule to cache the node after saving it?

gregarios’s picture

are you using any kind of rule to cache the node after saving it?

No special rules that I know of... I'm not sure what rules do you mean. The page is set to be allowed caching by boost. The settings are to cache it and keep it cached unless something on the page changes or the site cache is deleted. I do have these rules checked:

• Do not cache if php error on page
• Do not cache if a message is on the page
• Clear all cached terms pages associated with a node on insert/update/delete
• Check database timestamps for any site changes. Only if there has been a change will boost flush the expired content on cron.
• Asynchronous Operation: output HTML, close connection, then store static file.
• Clear all empty folders from cache.
• Clear all cached views pages associated with a node on update/delete
• Only allow ASCII characters in path

I'm not using the cron crawler, nor am I using menu functions, and 'Ignore cache flushing' is disabled.

mikeytown2’s picture

I was thinking something along these lines
http://drupal.org/node/583264#rules

Does the URL for error on the original post (nid:15589) match the URL for the node you just created (nid:15589); or are they not related?

gregarios’s picture

Oh... I'm not using the 'Rules' module at all. I let the next visitor's hit cache it -- which surely didn't come less than a second after I created it.

The two log entries I posted come right after the node's initial creation -- one right after the other -- in the same second even. I didn't modify a node a second time to get those.

mikeytown2’s picture

Based off the errors you give me and the way boost works; something hit that page as an anonymous user right after the node was created. How often does this error happen?

for the mysql has gone away here is a good starting point
http://drupal.org/node/259580

gregarios’s picture

Based off the errors you give me and the way boost works; something hit that page as an anonymous user right after the node was created. How often does this error happen?

This is not the case. I have a test site that is completely inaccessible from the internet, and I still get the error when I create the node from my local computer. It doesn't happen every time, but about once every 8 nodes I create it seems. Could another module be modifying it right after it is submitted each time... like maybe Nodewords?

mikeytown2’s picture

if you can reproduce this behavior in a controlled environment, then that's a good thing. Quick question, are you creating these nodes as an anonymous user? if yes then that explains the timing of everything. If not then your guess about another module hitting the newly created node could be correct.

In any case, turning boost verbose up to 9 should give you more info on what is happening; just be sure to match up the debug output with the error message when it happens.

gregarios’s picture

I actually don't use the DBlog, because I have Drupal log to syslog. Does the verbosity setting control what gets logged to syslog as well?

I create all nodes as the superuser.

I'm somewhat lacking enough time to do much testing in the controlled environment... as I only witnessed it once there during controlled testing of some css stuff. I have seen it happen a number of times on my live site, though, and the second hit to the newly created node always occurs in the exact same second it was created... so it must be something happening during creation time.

When it happens, it also screws up the Advertisement (http://drupal.org/project/ad) file cache, which must then be flushed manually to get ads to show again.

Other modules that function during creation time which I have enabled:

As you can see, figuring out which one is causing this problem, when the problem only happens once or twice a day, may be nearly impossible for me. We may have to wait until someone else sees this with less modules installed.

AlexisWilke’s picture

mickey,

I got that error today.

The function is well written except that you do not take parallelism in account. For that you need to lock the table so a 2nd attempt will block at the lock and not have a chance to run the UPDATE before the other attempt does the INSERT.

md5() returning the same number is close to impossible for file names.

Unfortunately, if only the UPDATE is necessary, the lock will penalize the 2nd user... but it is so fast that I don't think you'd be able to notice.

function boost_put_db($filename, $expire, $lifetime, $push, $router_item, $timer, $timer_average, $extension) {
  global $base_root;
  $url = $base_root . request_uri();
  $hash = md5($filename);
  $hash_url = md5($url);

  db_lock_table('boost_cache');   // make sure only one user at a time does UPDATE + INSERT

  db_query("UPDATE {boost_cache} SET expire = %d, lifetime = %d, push = %d, page_callback = '%s', page_type = '%s', timer = %d, timer_average = %d, base_dir = '%s', page_id = '%s', extension = '%s', url = '%s', filename = '%s', hash_url = '%s' WHERE hash = '%s'", $expire, $lifetime, $push, $router_item['page_callback'], $router_item['page_type'], $timer, $timer_average, BOOST_FILE_PATH, $router_item['page_id'], $extension, $url, $filename, $hash_url, $hash);
  if (!db_affected_rows()) {
    db_query("INSERT INTO {boost_cache} (hash, hash_url, filename, expire, lifetime, push, page_callback, page_type, timer, timer_average, base_dir, page_id, extension, url) VALUES ('%s', '%s', '%s', %d, %d, %d, '%s', '%s', %d, %d, '%s', '%s', '%s', '%s')", $hash, $hash_url, $filename, $expire, $lifetime, $push, $router_item['page_callback'], $router_item['page_type'], $timer, $timer_average, BOOST_FILE_PATH, $router_item['page_id'], $extension, $url);
  }

  db_unlock_tables();  // we're done

}
mikeytown2’s picture

added "@" to the front of the insert command; it's now in cvs.

AlexisWilke’s picture

Wow! Adding an @ is a kludge?! #12 is the right way.

mikeytown2’s picture

This operation doesn't need to be acid; if the insert fails because the entry now exists where as 0.1 seconds ago it didn't, it really doesn't matter. Certain things like this don't need to be exact. Both threads will be trying to insert the exact same info, therefore we can let one fail and not worry about it.

Examples of this in core:
http://api.drupal.org/api/function/cache_set/6
http://api.drupal.org/api/function/variable_set/6
http://api.drupal.org/api/function/sess_write/6
http://api.drupal.org/api/function/_update_cache_set/6

AlexisWilke’s picture

I don't doubt that it certainly doesn't matter much, but to me it looks wrong... Not like I write perfect code all the time either! 8-)

Now if you look at the sample error the 1st person posted, the two statements are not the same. Those 3 fields differ:

* expire
* timer
* timer_average

If that is fine, then we're good with an @.

Thank you.
Alexis

mikeytown2’s picture

Status: Active » Fixed

timer is how long it took for the page to be generated... no big deal.
timer_average is incorrect since we have 2 samples; not having exact stats vs locking a table, I'll go for the fuzzy math. Locking tables should be avoided at all costs.
expire is off by 1 second 1262470068 vs 1262470067; think we are good.

marking this fixed... let me know if something else comes up, seems like theres more in this thread then a simple '@' fix.

gregarios’s picture

Hey... I just noticed the IP addresses are different on those errors as well.. What the... Ah ha... the first one is a Google IP. I wonder now if this is an intermittent problem Boost is having with the Google News Sitemap or XML Sitemap modules...

mikeytown2’s picture

Well with this patch in place let me know if anything strange happens; at least we know it's 2 different computers accessing the same un-cached page at the same time.

Status: Fixed » Closed (fixed)

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