".generating" entries in database without nfs data counterpart brings apache to endless loop

« 
Previous topic
|
Developer
|
Next topic
 »
Author Message

Ekkehard Dörre

Saturday 16 April 2011 8:25:19 am

Hi togehther,

we have interesing challenges with eZDFSCluster

  • eZ Publish 4.4
  • 3 Frontend Server
  • 1 DB Server
  • eZDFSCluster running since more than one year with 4.2
  • NFS

This time the entry in ez-dfs.ezdfsfile was:

mysql> SELECT COUNT(*) FROM ezdfsfile WHERE name LIKE 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating';
+----------+
| COUNT(*) |
+----------+
|        1 |
SELECT * FROM ezdfsfile WHERE name LIKE  'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating';
+-----------------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------+----------------------------------+----------+-------+------+------------+---------+--------+
| name | name_trunk
 | name_hash | datatype | scope | size | mtime | expired | status |
+-----------------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------+----------------------------------+----------+-------+------+------------+---------+--------+
|   var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating  |  var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating  | bc591a4098b2389054e7e8b5709c9c06 | | | 0 | 1302170065 | 0 | 0 |
+-----------------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------+----------------------------------+----------+-------+------+------------+---------+--------+

Server3:/VIRTUAL/nfs/ez-dfs-data # ll var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating

ls: cannot access var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating: No such file or directory

Server1:/VIRTUAL/chroot/apache-php5.3/home/http/ezpublish-4.4/www/var/log # tail -f cluster.log

[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:24 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'
[ Apr 14 2011 19:25:25 ] An error occured starting cache generation on 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating'

The endless loop was on all 3 APP Servers (Server1, Server2, Server3).
!Emergency solution!

DELETE FROM ezdfsfile WHERE name LIKE 'var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE/Ich-habe-gewonnen.jpg.generating';

and restart all apaches
In nfs it looks now:

Server3:/VIRTUAL/nfs/ez-dfs-data # ls -l var/customer_site/storage/images/media/images/ich-habe-gewonnen/3247963-2-ger-DE
total 5580
-rw-r--r-- 1 wwwrun www    5299 Apr 14 19:33 Ich-habe-gewonnen_image_219x116.jpg
-rw-r--r-- 1 wwwrun www 5668810 Mar 29 12:12 Ich-habe-gewonnen.jpg
-rw-r--r-- 1 wwwrun www    8531 Mar 29 12:12 Ich-habe-gewonnen_large.jpg
-rw-r--r-- 1 wwwrun www   24511 Mar 29 12:12 Ich-habe-gewonnen_reference.jpg

It was trying to generate:
Ich-habe-gewonnen_image_219x116.jpg

a deeper look into ezpublish-4.4.0/kernel/private/classes/clusterfilehandlers/ezdfsfilehandler.php
line 846 tells us a little abot this .generating

// the .generating file is stored to DFS. $storeLocally is set to false
        // since we don't want to store the .generating file locally, only
        // the final file.
        $this->storeContents( $binaryData, $scope, $datatype, $storeLocally = false );

        // we end the cache generation process, so that the .generating file
        // is removed (we don't need to rename since contents was already stored
        // above, using fileStoreContents
        $this->endCacheGeneration();

the error message "An error occured starting cache generation on" is in ezpublish-4.4.0/kernel/private/classes/clusterfilehandlers/ezdfsfilehandler.php in line 1269

/**
    * Starts cache generation for the current file.
    *
    * This is done by creating a file named by the original file name, prefixed
    * with '.generating'.
    *
    * @return bool false if the file is being generated, true if it is not
    **/
    public function startCacheGeneration()
    {
        eZDebugSetting::writeDebug( 'kernel-clustering', "Starting cache generation", "dfs::startCacheGeneration( '{$this->filePath}' )" );

        $generatingFilePath = $this->filePath . '.generating';
        $ret = self::$dbbackend->_startCacheGeneration( $this->filePath, $generatingFilePath );

        // generation granted
        if ( $ret['result'] == 'ok' )
        {
            eZClusterFileHandler::addGeneratingFile( $this );
            $this->realFilePath = $this->filePath;
            $this->filePath = $generatingFilePath;
            $this->generationStartTimestamp = $ret['mtime'];
            return true;
        }
        // failure: the file is being generated
        elseif ( $ret['result'] == 'ko' )
        {
            return $ret['remaining'];
        }
        // unhandled error case, should not happen
        else
        {
            eZLog::write( "An error occured starting cache generation on '$generatingFilePath'", 'cluster.log' );
            return false;
        }
    }

I love the comment: "unhandled error case, should not happen"

another one about _generating_:

@ll var/ezflow_site/cache/template-block/3/2/3/3231593316.cache@


-rw-r--r-- 1 wwwrun www 38255 Apr 14 14:08 var/ezflow_site/cache/template-block/3/2/3/3231593316.cache


@mysql> SELECT name, FROM_UNIXTIME(mtime) FROM ezdfsfile WHERE name LIKE 'var/ezflow_site/%.generating';@


+------------------------------------------------------------------------+----------------------+
| name                                                                   | FROM_UNIXTIME(mtime) |
+------------------------------------------------------------------------+----------------------+
| var/ezflow_site/cache/template-block/3/2/3/3231593316.cache.generating | 2011-04-14 19:33:23  |
+------------------------------------------------------------------------+----------------------+

Any ideas to prevent this in future?
Thanks and greetings, ekke

http://www.coolscreen.de - Over 40 years of certified eZ Publish know-how: http://www.cjw-network.com
CJW Newsletter: http://projects.ez.no/cjw_newsletter - http://cjw-network.com/en/ez-publ...w-newsletter-multi-channel-marketing

Gaetano Giunta

Monday 18 April 2011 1:35:56 am

- most likely you have an 'exit' call in some php code that is run from within a node template

- this is a known bug, fixed in the 4.5 release

- if you found a similar but yet unhandled case, plese file anew bug

ciao

gaetano

Principal Consultant International Business
Member of the Community Project Board

Ekkehard Dörre

Monday 18 April 2011 2:44:20 am

Hi Gaetano,

thanks for the advice,

this seems to be the bug report: http://issues.ez.no/IssueView.php?Id=17148

We'll look into the templates and we'll report it.

Greetings ekke

http://www.coolscreen.de - Over 40 years of certified eZ Publish know-how: http://www.cjw-network.com
CJW Newsletter: http://projects.ez.no/cjw_newsletter - http://cjw-network.com/en/ez-publ...w-newsletter-multi-channel-marketing
Powered by eZ Publish™ CMS Open Source Web Content Management. Copyright © 1999-2014 eZ Systems AS (except where otherwise noted). All rights reserved.