"Duplicate entry" database error when fast clicking the next image link two times

TuXator

Joined: 2009-05-13
Posts: 11
Posted: Sat, 2009-08-29 16:56

Hi!

I think I am experiencing a race condition in cache maintainance:
When browsing images, ERROR_STORAGE_FAILURE is raised, if I fast click the next image button two times:

Quote:
Database Error

An error has occurred while interacting with the database.

Back to the Gallery
Error Detail -
Error (ERROR_STORAGE_FAILURE)

* in modules/core/classes/GalleryStorage/GalleryStorageExtras.class at line 1007 (GalleryCoreApi::error)
* in modules/core/classes/GalleryStorage.class at line 521 (GalleryStorageExtras::addMapEntry)
* in modules/core/classes/GalleryCoreApi.class at line 2956 (GalleryStorage::addMapEntry)
* in modules/core/classes/GalleryDataCache.class at line 692 (GalleryCoreApi::addMapEntry)
* in modules/core/classes/GalleryTheme.class at line 1839 (GalleryDataCache::putPageData)
* in /etc/gallery2/themes/leosiriux/theme.inc at line 177 (GalleryTheme::loadCommonTemplateData)
* in modules/core/classes/GalleryTheme.class at line 943 (LeoSiriuxTheme::showPhotoPage)
* in modules/core/classes/GalleryView.class at line 301 (GalleryTheme::loadTemplate)
* in main.php at line 465 (GalleryView::doLoadTemplate)
* in main.php at line 104
* in /home/srv/gallery2/htdocs/index.php at line 17

It looks like gallery tries to insert the same cache map entry two times.
The log file states a "Duplicate entry" in g2_CacheMap:

Quote:
2009-08-29 17:46:11 [TMP_SESSION_ID_DI_NOISSES_PMT] mysqli error: [1062: Duplicate entry '661f1ac863e7d8f8b00b47269d4d4982-5-26977-template' for key 1] in EXECUTE("INSERT INTO g2_CacheMap (g_key, g_value, g_userId, g_itemId, g_type, g_timestamp, g_isEmpty) VALUES ('661f1ac863e7d8f8b00b47269d4d4982',

I found an old bugfix that might be related and is, of course, included in my gallery version. But somehow this fix is not effective in my case.

Any hints?

Thanks,
--leo


Gallery version (not just "2"): 2.3 (Fedora 10)
PHP version (e.g. 5.1.6): 5.2.9
Webserver (e.g. Apache 1.3.33): 2.2.11
Database (e.g. MySql 5.0.32): 5.0.77
Operating system (e.g. Linux): Linux (Fedora 10)
Browser (e.g. Firefox 2.0): FF 3.0.11
 
nivekiam
nivekiam's picture

Joined: 2002-12-10
Posts: 16504
Posted: Wed, 2009-09-02 02:14

Don't know what to say other than don't do that or upgrade to G3 when it's released :)

I can't duplicate this so I can't trouble shoot it. I wouldn't even know where to start on something like this.
____________________________________________
Like Gallery? Like the support? Donate now!!! See G2 live here
 
nivekiam
nivekiam's picture

Joined: 2002-12-10
Posts: 16504
Posted: Wed, 2009-09-02 02:14

Oh and have you tried clearing the cache?
____________________________________________
Like Gallery? Like the support? Donate now!!! See G2 live here
 
TuXator

Joined: 2009-05-13
Posts: 11
Posted: Fri, 2009-12-18 21:36

Are there any new findings about this problem?
I'm still getting these errors.
And yes, I did clear the template and database caches.

Thanks,
--leo
 
alecmyers

Joined: 2006-08-01
Posts: 4342
Posted: Sat, 2009-12-19 01:35

Reminds me of the old Tommy Cooper joke:

"Doctor, it hurts when I go like <this>, and like <this> and like <this> - what should I do?"
"Don't go like <this>!"

Sorry, just thought I'd say. It's quite unlikely that any progress would be made since G2 development has effectively ceased (more than a year ago).

 
TuXator

Joined: 2009-05-13
Posts: 11
Posted: Sat, 2009-12-19 09:42

Unfortunately I cannot remote control my users, I cannot dictate their click speed while browsing.

It is a problem that can be reproduced not only on my but on many other galleries out there. That's why I hoped that maybe someone has already solved it.

E.g. see some of the demosites:
http://www.car-pictures.us/renault/classic/1982_Renault_4_GTL.jpg.html
http://agm-foto.de/v/Sonnenuntergaenge/radbodsee-x-IIIIII.jpg.html

Just browse to the above URLs using Firefox and double-click the gallery next-Buttons or double-click the browsers Reload-Button. For a script-approach, see below.

And just because development focuses on gallery3 now, it doesn't mean that no gallery2 bugs should be fixed anymore, does it?

I'd really like to fix it myself. But I did already spend many hours digging the code and I simply didn't manage it. So I'd be very grateful if some expert could take a look at it.

Cheers,
--leo

P.S.: It can be easily reproduced without browser using the following small script: (save it as doubleget.sh)

Quote:
#!/bin/sh

wget -nv -O/dev/null "$1" &
wget -nv -O/dev/null "$1" &
wait

E.g:

Quote:
sh doubleget.sh "http://www.car-pictures.us/renault/classic/1982_Renault_4_GTL.jpg.html"
http://www.car-pictures.us/renault/classic/1982_Renault_4_GTL.jpg.html:
2009-12-19 10:37:03 ERROR 500: Internal Server Error.
2009-12-19 10:37:04 URL:http://www.car-pictures.us/renault/classic/1982_Renault_4_GTL.jpg.html [17736] -> "/dev/null" [1]

 
alecmyers

Joined: 2006-08-01
Posts: 4342
Posted: Sat, 2009-12-19 14:21
Quote:
And just because development focuses on gallery3 now, it doesn't mean that no gallery2 bugs should be fixed anymore, does it?

No I totally agree, if it's a bug it should be fixed.

But from the point of view of facts-on-the-ground, none of the development team (a very small team) are working on G2 any more to the extent of providing bug fixes, and there are unlikely ever to be any more official releases (G2.3.1 was just released with the bare minimum of changes to support php 5.3, no bug fixes) so as far as official code goes, I'm just saying, don't hold your breath.

Quote:
I'd really like to fix it myself.

That still remains your most likely source for a fix.
 
nivekiam
nivekiam's picture

Joined: 2002-12-10
Posts: 16504
Posted: Sat, 2009-12-19 18:55

2009-12-19 10:37:03 ERROR 500: Internal Server Error.

AH HA What's the error message in your server's error log?

Just as I was starting to suspect, it's something going on on the server. I still can't reproduce this on two different servers with 2 different setups.

It also doesn't happen to me here:
http://agm-foto.de/v/Sonnenuntergaenge/radbodsee-x-IIIIII.jpg.html

But it does here:
http://www.car-pictures.us/renault/classic/1982_Renault_4_GTL.jpg.html

I can only think that something is happening at the server to cause an error.
____________________________________________
Like Gallery? Like the support? Donate now!!! See G2 live here
 
alecmyers

Joined: 2006-08-01
Posts: 4342
Posted: Sat, 2009-12-19 19:03

I can't reproduce it either, but I have a fast server.
 
nivekiam
nivekiam's picture

Joined: 2002-12-10
Posts: 16504
Posted: Sat, 2009-12-19 19:17

So are both of mine and I can't tell if the agm-foto site is on a slow server or it's just a slow connection for me in the US.
____________________________________________
Like Gallery? Like the support? Donate now!!! See G2 live here
 
alecmyers

Joined: 2006-08-01
Posts: 4342
Posted: Sat, 2009-12-19 19:40

Yes, I see what you mean. I agree with you that it looks server-related rather than a G2 issue.
 
Dayo

Joined: 2005-11-04
Posts: 1642
Posted: Sat, 2009-12-19 21:39

Tried all the sites listed here including mine and can't replicate this issue.

--
dakanji.com
 
TuXator

Joined: 2009-05-13
Posts: 11
Posted: Mon, 2009-12-21 11:06

It is not a problem with the server, it's a race condition.
That's why it depends on the distance (round trip time) to the server or on the delay between two clicks.
Maybe you have to try it several times before the error occurs or maybe you have to add something like "usleep 10000" between the two wget's. Or maybe it depends on the installed plugins or themes but it's definitely not a server problem.

I suppose it must be something like that: (see the DB operations on cache item 661f.. in the above logfile.)

  • Request1 tries to update the CacheMap table. The update fails because there is currently no corresponding row with key 661f..
  • Request2 also tries to update the CacheMap table. The update fails because there is currently no corresponding row with key 661f..
  • Request1 does a GalleryCoreApi::addMapEntry.
  • Request2 also tries to add the entry. This INSERT fails because Request1 did already do it.

See http://sourceforge.net/apps/trac/gallery/browser/tags/RELEASE_2_3_1/gallery2/modules/core/classes/GalleryDataCache.class?rev=20963#L676
for the corresponding code lines and http://sourceforge.net/apps/trac/gallery/changeset/17022 for a related patch that somehow doesn't work for me.

Normally, the following code should catch that error but somehow it doesn't seem to work in my case...

Quote:
693 if ($ret) {
694 /*
695 * Nearly always this update/insert should be OK in one pass.
696 * However, 2 simultaneous requests may both fail to update, then both
697 * try to insert.. the 2nd insert will fail. In this rare case we'll
698 * loop and try once more to update.. if it still fails we'll error out.
699 */
700 if ($i < 1) {
701 continue;
702 }
703 return $ret;
704 }

It looks like I'll have to add some debugging code around that piece of code. Besides, the process-ids will be helpful to separate the two requests...

Cheers,
--leo
 
alecmyers

Joined: 2006-08-01
Posts: 4342
Posted: Mon, 2009-12-21 11:15
Quote:
Normally, the following code should catch that error but somehow it doesn't seem to work in my case...

That might be the server-related bit.
 
TuXator

Joined: 2009-05-13
Posts: 11
Posted: Tue, 2009-12-22 12:37

OK, I finally nailed it down.

The Problem is that $storage->getAffectedRows() only returns 1 if any data has actually been changed!
This seems to be a known problem in mysqli.

If the second UPDATE comes within the same second, the values to update are identically to the values that have already been written by the first request. So $storage->getAffectedRows() thinks that the UPDATE didn't match any row and tries an INSERT. This, of course fails, another UPDATE is done, which yields affectedRows=0 again. And the second INSERT causes the ERROR_STORAGE_FAILURE.

So I guess this error must be reproducable on all boxes running mysql with the mysqli driver...

Cheers,
--leo

Update: not only the mysqli but also the older mysql driver shows the same behavior.
 
TuXator

Joined: 2009-05-13
Posts: 11
Posted: Tue, 2009-12-22 13:03

Unfortunately there is no database independent way of getting the number of rows matched (as opposed to the number of rows changed) by the the UPDATE in GalleryCoreApi::updateMapEntry().

The following suboptimal patch fixes the problem for now.

--- modules/core/classes/GalleryDataCache.class.orig    2009-12-22 13:41:18.367594744 +0100
+++ modules/core/classes/GalleryDataCache.class 2009-12-22 13:50:06.871852027 +0100
@@ -685,7 +685,13 @@
                return $ret;
            }

-           if (!$affectedRows) {
+           /* Note: when using mysql or mysqli, getAffectedRows() returns the number of rows
+              actually _changed_ (not the number of rows that _matched_ the WHERE clause).
+              If there is more than one update on the same item in the same second,
+              $affectedRows will be 0 even though the corresponding row is in the
+              CacheMap, just because the same data will be inserted (updated) twice
+              If we are here for the second time, it might be because of that problem. */
+           if ($i < 1 && !$affectedRows) {
                $ret = GalleryCoreApi::addMapEntry(
                    'GalleryCacheMap',
                    array('key' => $key, 'value' => $value, 'userId' => $userId, 'type' => $type,
 
floridave
floridave's picture

Joined: 2003-12-22
Posts: 27300
Posted: Tue, 2009-12-22 14:38

TuXator,
Thanks for your debugging and patch. Can you add it to the http://sourceforge.net/tracker/?group_id=7130&atid=307130
Then it will not get lost and the next person who feels like doing anther G2 release will be able to implement it.

Dave
_____________________________________________
Blog & G2 || floridave - Gallery Team