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

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

eZ debug

Timing: Jan 17 2025 23:40:36
Script start
Timing: Jan 17 2025 23:40:36
Module start 'content'
Timing: Jan 17 2025 23:40:38
Module end 'content'
Timing: Jan 17 2025 23:40:38
Script end

Main resources:

Total runtime1.6306 sec
Peak memory usage4,096.0000 KB
Database Queries194

Timing points:

CheckpointStart (sec)Duration (sec)Memory at start (KB)Memory used (KB)
Script start 0.00000.0096 589.4453180.7734
Module start 'content' 0.00961.4973 770.2188599.2813
Module end 'content' 1.50690.1237 1,369.5000344.6953
Script end 1.6306  1,714.1953 

Time accumulators:

 Accumulator Duration (sec) Duration (%) Count Average (sec)
Ini load
Load cache0.00420.2547210.0002
Check MTime0.00160.0976210.0001
Mysql Total
Database connection0.00090.057510.0009
Mysqli_queries1.555395.38261940.0080
Looping result0.00240.14681920.0000
Template Total1.581197.020.7906
Template load0.00220.133920.0011
Template processing1.578996.829820.7895
Template load and register function0.00010.006410.0001
states
state_id_array0.00220.133810.0022
state_identifier_array0.00180.110620.0009
Override
Cache load0.00190.1143560.0000
Sytem overhead
Fetch class attribute can translate value0.00170.104130.0006
Fetch class attribute name0.00140.084550.0003
XML
Image XML parsing0.00120.075830.0004
class_abstraction
Instantiating content class attribute0.00000.000760.0000
General
dbfile0.00230.1383330.0001
String conversion0.00000.000430.0000
Note: percentages do not add up to 100% because some accumulators overlap

CSS/JS files loaded with "ezjscPacker" during request:

CacheTypePacklevelSourceFiles
CSS0extension/community/design/community/stylesheets/ext/jquery.autocomplete.css
extension/community_design/design/suncana/stylesheets/scrollbars.css
extension/community_design/design/suncana/stylesheets/tabs.css
extension/community_design/design/suncana/stylesheets/roadmap.css
extension/community_design/design/suncana/stylesheets/content.css
extension/community_design/design/suncana/stylesheets/star-rating.css
extension/community_design/design/suncana/stylesheets/syntax_and_custom_tags.css
extension/community_design/design/suncana/stylesheets/buttons.css
extension/community_design/design/suncana/stylesheets/tweetbox.css
extension/community_design/design/suncana/stylesheets/jquery.fancybox-1.3.4.css
extension/bcsmoothgallery/design/standard/stylesheets/magnific-popup.css
extension/sevenx/design/simple/stylesheets/star_rating.css
extension/sevenx/design/simple/stylesheets/libs/fontawesome/css/all.min.css
extension/sevenx/design/simple/stylesheets/main.v02.css
extension/sevenx/design/simple/stylesheets/main.v02.res.css
JS0extension/ezjscore/design/standard/lib/yui/3.17.2/build/yui/yui-min.js
extension/ezjscore/design/standard/javascript/jquery-3.7.0.min.js
extension/community_design/design/suncana/javascript/jquery.ui.core.min.js
extension/community_design/design/suncana/javascript/jquery.ui.widget.min.js
extension/community_design/design/suncana/javascript/jquery.easing.1.3.js
extension/community_design/design/suncana/javascript/jquery.ui.tabs.js
extension/community_design/design/suncana/javascript/jquery.hoverIntent.min.js
extension/community_design/design/suncana/javascript/jquery.popmenu.js
extension/community_design/design/suncana/javascript/jScrollPane.js
extension/community_design/design/suncana/javascript/jquery.mousewheel.js
extension/community_design/design/suncana/javascript/jquery.cycle.all.js
extension/sevenx/design/simple/javascript/jquery.scrollTo.js
extension/community_design/design/suncana/javascript/jquery.cookie.js
extension/community_design/design/suncana/javascript/ezstarrating_jquery.js
extension/community_design/design/suncana/javascript/jquery.initboxes.js
extension/community_design/design/suncana/javascript/app.js
extension/community_design/design/suncana/javascript/twitterwidget.js
extension/community_design/design/suncana/javascript/community.js
extension/community_design/design/suncana/javascript/roadmap.js
extension/community_design/design/suncana/javascript/ez.js
extension/community_design/design/suncana/javascript/ezshareevents.js
extension/sevenx/design/simple/javascript/main.js

Templates used to render the page:

UsageRequested templateTemplateTemplate loadedEditOverride
1node/view/full.tplfull/forum_topic.tplextension/sevenx/design/simple/override/templates/full/forum_topic.tplEdit templateOverride template
3content/datatype/view/ezimage.tpl<No override>extension/sevenx/design/simple/templates/content/datatype/view/ezimage.tplEdit templateOverride template
3content/datatype/view/ezxmltext.tpl<No override>extension/community_design/design/suncana/templates/content/datatype/view/ezxmltext.tplEdit templateOverride template
11content/datatype/view/ezxmltags/paragraph.tpl<No override>extension/ezwebin/design/ezwebin/templates/content/datatype/view/ezxmltags/paragraph.tplEdit templateOverride template
1content/datatype/view/ezxmltags/li.tpl<No override>design/standard/templates/content/datatype/view/ezxmltags/li.tplEdit templateOverride template
1content/datatype/view/ezxmltags/ul.tpl<No override>design/standard/templates/content/datatype/view/ezxmltags/ul.tplEdit templateOverride template
7content/datatype/view/ezxmltags/literal.tpl<No override>extension/community/design/standard/templates/content/datatype/view/ezxmltags/literal.tplEdit templateOverride template
5content/datatype/view/ezxmltags/line.tpl<No override>design/standard/templates/content/datatype/view/ezxmltags/line.tplEdit templateOverride template
1content/datatype/view/ezxmltags/emphasize.tpl<No override>design/standard/templates/content/datatype/view/ezxmltags/emphasize.tplEdit templateOverride template
1pagelayout.tpl<No override>extension/sevenx/design/simple/templates/pagelayout.tplEdit templateOverride template
 Number of times templates used: 34
 Number of unique templates used: 10

Time used to render debug report: 0.0002 secs