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

".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

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