Item10987: MongoDBPlugin borks FoswikI::Form $session->{forms} "cache" because constructor is never called properly

Symptom: sometimes, the edit screen fails to render a form.

This is because Foswiki::Form->renderForEdit() doesn't bother re-parsing the topic text for field definitions if it's already in the $session->{forms} cache.

These commented-out lines are the culprit (but commenting out these lines causes other issues):

diff --git a/lib/Foswiki/Plugins/MongoDBPlugin/Listener.pm b/lib/Foswiki/Plugins/MongoDBPlugin/Listener.pm
index d80975e..6c7c98c 100644
--- a/lib/Foswiki/Plugins/MongoDBPlugin/Listener.pm
+++ b/lib/Foswiki/Plugins/MongoDBPlugin/Listener.pm
@@ -218,13 +218,13 @@ sub loadTopic {
     bless( $_[1], 'Foswiki::Plugins::MongoDBPlugin::Meta' );
     $_[1]->reload();    #get the latest version
     $_[1]->{_latestIsLoaded} = 1;
-    if ( $_[1]->topic =~ /Form$/ ) {
-        use Foswiki::Form;
-        bless( $_[1], 'Foswiki::Form' );
-
-        $session->{forms}->{ $_[1]->web . '.' . $_[1]->topic } = $_[1];
-        print STDERR "------ init Form obj\n" if MONITOR;
-    }
+#    if ( $_[1]->topic =~ /Form$/ ) {
+#        use Foswiki::Form;
+#        bless( $_[1], 'Foswiki::Form' );
+#
+#        $session->{forms}->{ $_[1]->web . '.' . $_[1]->topic } = $_[1];
+#        print STDERR "------ init Form obj\n" if MONITOR;
+#    }
 
     $session->search->metacache->addMeta( $_[1]->web, $_[1]->topic, $_[1] );
     

MongoDBPlugin is just blessing Foswiki::Form objects directly, and the Foswiki::Form->new() constructor is never called.

So we end up with unparsed Foswiki::Form objects in the $session->{forms} cache.

Need to figure out if random occurrences where supposedly $formObj things are actually Foswiki::Meta (eg. calls to ->getAvailableForms fail) are linked to this problem.

Here's the patch I implemented as a temporary work-around:

diff --git a/lib/Foswiki/Form.pm b/lib/Foswiki/Form.pm
index 261e201..c270e0a 100644
--- a/lib/Foswiki/Form.pm
+++ b/lib/Foswiki/Form.pm
@@ -75,7 +75,7 @@ sub new {
     my ( $class, $session, $web, $form, $def ) = @_;
 
     my $this = $session->{forms}->{"$web.$form"};
-    unless ($this) {
+    unless ($this and $this->{_parsed}) {
 
         # A form name has to be a valid topic name after normalisation
         my ( $vweb, $vtopic ) = $session->normalizeWebTopicName( $web, $form );
@@ -106,6 +106,7 @@ sub new {
 
         $this = $class->SUPER::new( $session, $vweb, $vtopic );
         $session->{forms}->{"$web.$form"} = $this;
+        $this->{_parsed} = 1;
 
         unless ( $def || $this->haveAccess('VIEW') ) {
             throw Foswiki::AccessControlException( 'VIEW', $session->{user},
@@ -396,6 +397,8 @@ sub renderForEdit {
     my ( $text, $repeatTitledText, $repeatUntitledText, $afterText ) =
       split( /%REPEAT%/, $tmpl );
 
+    #require Data::Dumper;
+    #Foswiki::Func::writeDebug("fieldDef: " . Data::Dumper->Dump([$this]));
     foreach my $fieldDef ( @{ $this->{fields} } ) {
 
         my $value;

-- PaulHarvey - 19 Jul 2011

This is still busted:

Can't locate object method "getFields" via package "Foswiki::Plugins::MongoDBPlugin::Meta" at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/Plugins/JQGridPlugin/GRID.pm line 221.
 at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/Plugins/JQGridPlugin/GRID.pm line 221
   Foswiki::Plugins::JQGridPlugin::GRID::handleGrid('Foswiki::Plugins::JQGridPlugin::GRID=HASH(0x41c0938)', 'Foswiki::Attrs=HASH(0x39862d8)', 'Taxa', 'TaxonProfile/Builder', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0x3985758)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/Plugins/JQGridPlugin.pm line 60
   Foswiki::Plugins::JQGridPlugin::handleGrid('Foswiki=HASH(0x1b76778)', 'Foswiki::Attrs=HASH(0x39862d8)', 'Taxa', 'TaxonProfile/Builder', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0x3985758)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/Func.pm line 568
   Foswiki::Func::__ANON__('Foswiki=HASH(0x1b76778)', 'Foswiki::Attrs=HASH(0x39862d8)', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0x3985758)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki.pm line 3064
   Foswiki::_expandMacroOnTopicRendering('Foswiki=HASH(0x1b76778)', 'GRID', '
   query="form.name"
   fields="Topic,Modified,By,PlumeMoths...', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0x3985758)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki.pm line 2940
   Foswiki::_processMacros('Foswiki=HASH(0x1b76778)', '---++ All Taxa

[[%BASEWEB%.TaxonCreator][ %ICON{"newtopic"}%...', 'CODE(0x1adb188)', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0x3985758)', 16) called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki.pm line 2737
   Foswiki::innerExpandMacros('Foswiki=HASH(0x1b76778)', 'SCALAR(0x37ce280)', 'Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0x3985758)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/Macros/INCLUDE.pm line 296
   Foswiki::__ANON__() called at /usr/share/perl5/Error.pm line 416
   eval {...} called at /usr/share/perl5/Error.pm line 408
   Error::subs::try('CODE(0x3f2c880)', 'HASH(0x3f2d420)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/Macros/INCLUDE.pm line 343
   Foswiki::INCLUDE('Foswiki=HASH(0x1b76778)', 'Foswiki::Attrs=HASH(0x3985380)', 'Foswiki::Meta=HASH(0x36a8610)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki.pm line 3064
   Foswiki::_expandMacroOnTopicRendering('Foswiki=HASH(0x1b76778)', 'INCLUDE', '"TaxonProfile/Builder.Taxa" NAMESPACE="PlumeMoths" DEFAULTPRO...', 'Foswiki::Meta=HASH(0x36a8610)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki.pm line 2940
   Foswiki::_processMacros('Foswiki=HASH(0x1b76778)', '%INCLUDE{"%BUILDERWEB%.%TOPIC%" NAMESPACE="PlumeMoths" DEFAUL...', 'CODE(0x1adb188)', 'Foswiki::Meta=HASH(0x36a8610)', 16) called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki.pm line 2737
   Foswiki::innerExpandMacros('Foswiki=HASH(0x1b76778)', 'SCALAR(0x36b4518)', 'Foswiki::Meta=HASH(0x36a8610)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki.pm line 3246
   Foswiki::expandMacros('Foswiki=HASH(0x1b76778)', '%INCLUDE{"%BUILDERWEB%.%TOPIC%" NAMESPACE="PlumeMoths" DEFAUL...', 'Foswiki::Meta=HASH(0x36a8610)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/Meta.pm line 3108
   Foswiki::Meta::expandMacros('Foswiki::Meta=HASH(0x36a8610)', '%INCLUDE{"%BUILDERWEB%.%TOPIC%" NAMESPACE="PlumeMoths" DEFAUL...') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/UI/View.pm line 406
   Foswiki::UI::View::_prepare('%INCLUDE{"%BUILDERWEB%.%TOPIC%" NAMESPACE="PlumeMoths" DEFAUL...', 'Foswiki::Meta=HASH(0x36a8610)', 0) called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/UI/View.pm line 386
   Foswiki::UI::View::view('Foswiki=HASH(0x1b76778)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/UI.pm line 316
   Foswiki::UI::__ANON__() called at /usr/share/perl5/Error.pm line 416
   eval {...} called at /usr/share/perl5/Error.pm line 408
   Error::subs::try('CODE(0x1458fb8)', 'HASH(0x1b8cc10)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/UI.pm line 435
   Foswiki::UI::_execute('Foswiki::Request=HASH(0x14827d0)', 'CODE(0x1b56918)', 'command_line', 1, 'view', 1) called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/UI.pm line 274
   Foswiki::UI::handleRequest('Foswiki::Request=HASH(0x14827d0)') called at /usr/local/src/wiki.trin.org.au/core/lib/Foswiki/Engine/CLI.pm line 53
   Foswiki::Engine::CLI::run('Foswiki::Engine::CLI=HASH(0x15087f0)') called at ./view line 29.
   (in cleanup)    (in cleanup) not an object during global destruction.
 at ./view line 0
   eval {...} called at ./view line 0

The fundamental problem is that the MongoDB store listener is "re-blessing" an object which is NOT a Foswiki::Meta (in fact, it is a Foswiki::Form which ISA Foswiki::Meta), as a Foswiki::Plugins::MongoDBPlugin::Meta.

THIS IS BAD

-- PaulHarvey - 04 Aug 2011

Happens trying to view PlumeMoths.Taxa

-- PaulHarvey - 04 Aug 2011

The problem is that Foswiki::Form->_parseFormDefinition() does this:

sub _parseFormDefinition {
     print STDERR 'Foswiki::Form: ' . ref($this) . "\n";
     my $text    = $this->text();
     print STDERR 'Now it\'s a Foswiki::Plugins::MongoDBPlugin::Meta!!! :' . ref($this) . "\n";

-- PaulHarvey - 04 Aug 2011

Here's a hack that seems to work:

diff --git a/lib/Foswiki/Plugins/MongoDBPlugin/Listener.pm b/lib/Foswiki/Plugins/MongoDBPlugin/Listener.pm
index 3dbfb95..c71abbf 100644
--- a/lib/Foswiki/Plugins/MongoDBPlugin/Listener.pm
+++ b/lib/Foswiki/Plugins/MongoDBPlugin/Listener.pm
@@ -202,7 +202,8 @@ sub loadTopic {
         #return;
         #query the versions collection - via  MongoDBPlugin::Meta 
         #rebless into a mighter version of Meta
-        bless( $_[1], 'Foswiki::Plugins::MongoDBPlugin::Meta' );
+        #bless( $_[1], 'Foswiki::Plugins::MongoDBPlugin::Meta' );
+        _mongofyClass(\$_[1]);
         $_[1]->reload($_[2]);    #get the requested version
         return ( $_[1]->getLoadedRev(), 1 );
     }
@@ -220,7 +221,8 @@ sub loadTopic {
     }
 
     #rebless into a mighter version of Meta
-    bless( $_[1], 'Foswiki::Plugins::MongoDBPlugin::Meta' );
+    #bless( $_[1], 'Foswiki::Plugins::MongoDBPlugin::Meta' );
+    _mongofyClass(\$_[1]);
     $_[1]->reload();    #get the latest version
     $_[1]->{_latestIsLoaded} = 1;
     if ( $_[1]->topic =~ /Form$/ ) {
@@ -244,6 +246,38 @@ sub loadTopic {
 
 }
 
+sub _mongofyClass {
+    my ($pObj) = @_;
+    my $class = ref(${$pObj});
+
+    ASSERT($class) if DEBUG;
+    if (not $class->isa('Foswiki::Plugins::MongoDBPlugin::Meta')) {
+        my $isaref = eval '\@' . $class . '::ISA';
+        my $foundit;
+        my $i = 0;
+        ASSERT(ref($isaref) eq 'ARRAY') if DEBUG;
+        my $nsuperclasses = scalar(@{$isaref});
+
+        #require Data::Dumper;
+        #print STDERR 'Before, ' . $class . ' ISA: ' . Data::Dumper->Dump([$isaref]);
+        ASSERT($class->isa('Foswiki::Meta')) if DEBUG;
+        while ( not $foundit and $i < $nsuperclasses ) {
+            if ($isaref->[$i] eq 'Foswiki::Meta') {
+                $isaref->[$i] = 'Foswiki::Plugins::MongoDBPlugin::Meta';
+                $foundit = 1;
+            }
+            $i += 1;
+        }
+        if (not $foundit) {
+            bless( ${$pObj}, 'Foswiki::Plugins::MongoDBPlugin::Meta' );
+        }
+        #print STDERR 'After, the ' . ref(${$pObj}) . ' obj ISA: ' . Data::Dumper->Dump([$isaref]);
+        ASSERT(${$pObj}->isa('Foswiki::Plugins::MongoDBPlugin::Meta'), "It's a " . $class . ', ' . ($foundit ||0)) if DEBUG;
+    }
+
+    return;
+}
+
 sub getRevisionHistory {
     my $this = shift;
     my $meta = shift;

-- PaulHarvey - 04 Aug 2011

mmm, ok, 2 big questoins:

1. where did you get the idea to do it this way, and
2. what exactly are you intending this code to do?

I think i grok what the code does, but I want to make sure that is the same as what you intend it to do :/ cos its not quite what i expected would work :/

I also only just now noticed the most important info Happens trying to view PlumeMoths.Taxa

excellent, I'll test that asap.

-- SvenDowideit - 07 Aug 2011

argh! course, viewing that topic is ok on my setup - I don't have the same plugins as you

-- SvenDowideit - 07 Aug 2011

even adding topic recurse plugin, it does not crash for me

I then grabbed the list of enabled plugins from the trin server, and made it into

• enable-trin-plugins.sh: pseudo-install trin plugins?

and even that does not crash on my system.

SO _ what the heck?

I do get

[Sun Aug 07 09:15:33 2011] [error] [client 127.0.1.1] [Sun Aug  7 09:15:33 2011] view: Argument "\\x{25}\\x{44}..." isn't numeric in numeric lt (<) at /home/sven/src/foswiki/core/lib/Foswiki/Plugins/TopicRecursePlugin/Node.pm line 136.
[Sun Aug 07 09:15:35 2011] [error] [client 127.0.1.1] [Sun Aug  7 09:15:35 2011] view: \t(in cleanup) not an object during global destruction.
[Sun Aug 07 09:15:35 2011] [error] [client 127.0.1.1] [Sun Aug  7 09:15:35 2011] view:  at /home/sven/src/foswiki/core/bin/view line 0
[Sun Aug 07 09:15:35 2011] [error] [client 127.0.1.1] [Sun Aug  7 09:15:35 2011] view: \teval {...} called at /home/sven/src/foswiki/core/bin/view line 0

in my log file tho

-- SvenDowideit - 07 Aug 2011

running as guest

-- SvenDowideit - 07 Aug 2011

educational reading:

• http://www.perlmonks.org/?node_id=555977
• http://www.perlmonks.org/?node_id=227847

-- PaulHarvey - 07 Aug 2011

The diff had a mistake checking $class->isa instead of ${$pObj}->isa, updated it

-- PaulHarvey - 11 Aug 2011

Paul, what happens when you run the FormDefTests?

I'm getting

1 failure:
FormDefTests::test_searchForOptions

Expected:'SplodgeOne,SplodgeTwo'
 But got:''
 at /home/sven/src/foswiki/core/lib/Unit/TestCase.pm line 271
   Unit::TestCase::assert_str_equals('FormDefTests=HASH(0x232a340)', 'SplodgeOne,SplodgeTwo', '') called at /home/sven/src/foswiki/core/test/unit/FormDefTests.pm line 214

when I've got mongoDB on..

-- SvenDowideit - 12 Aug 2011

On perl 5.12 I get a different error in FormDefTests::test_Item972_selectPlusValues:

   
*** Use of uninitialized value in concatenation (.) or string at /usr/local/src/github.com/foswiki/core/lib/Assert.pm line 95.
 at /usr/local/src/github.com/foswiki/core/test/unit/FoswikiTestCase.pm line 40
   FoswikiTestCase::__ANON__('Use of uninitialized value in concatenation (.) or string at ...') called at /usr/local/src/github.com/foswiki/core/lib/Foswiki.pm line 149
   Foswiki::__ANON__('Use of uninitialized value in concatenation (.) or string at ...') called at /usr/local/src/github.com/foswiki/core/lib/Assert.pm line 95
   Assert::TAINT(undef) called at /usr/local/src/github.com/foswiki/core/lib/Foswiki/Form/Select.pm line 59
   Foswiki::Form::Select::getOptions('Foswiki::Form::Select=HASH(0x269d510)') called at /usr/local/src/github.com/foswiki/core/test/unit/FormDefTests.pm line 286
   FormDefTests::test_Item972_selectPlusValues('FormDefTests=HASH(0x182fde0)') called at /usr/local/src/github.com/foswiki/core/lib/Unit/TestRunner.pm line 383
   Unit::TestRunner::__ANON__() called at /usr/local/src/github.com/foswiki/core/lib/CPAN/lib/Error.pm line 379
   eval {...} called at /usr/local/src/github.com/foswiki/core/lib/CPAN/lib/Error.pm line 371
   Error::subs::try('CODE(0x23c88e0)', 'HASH(0x23c5e78)') called at /usr/local/src/github.com/foswiki/core/lib/Unit/TestRunner.pm line 402
   Unit::TestRunner::runOne('FormDefTests=HASH(0x182fde0)', 'FormDefTests', undef) called at /usr/local/src/github.com/foswiki/core/lib/Unit/TestRunner.pm line 137
   Unit::TestRunner::start('Unit::TestRunner=HASH(0x14feb20)', 'FormDefTests.pm') called

-- PaulHarvey - 13 Aug 2011

Okay, I fixed the errors I was getting, and can confirm the same problem.

It seems there's something wrong with ^ anchor, at least

-- PaulHarvey - 13 Aug 2011

na, its escaping the pipe wrong - I opened a different task for it tho (i have some fixes i'm working on, will dcommit soon)

-- SvenDowideit - 13 Aug 2011

k, created a test that fails, here's the error with MongoDB enabled:

Running FormDefTests
   FormDefTests::test_Item10987_formObjClass
*** Can't locate object method "createField" via package "Foswiki::Plugins::MongoDBPlugin::Meta" at /usr/local/src/github.com/foswiki/core/lib/Foswiki/Form.pm line 262.
 at /usr/local/src/github.com/foswiki/core/test/unit/FoswikiTestCase.pm line 40
   FoswikiTestCase::__ANON__('Can\'t locate object method "createField" via package "Foswik...') called at /usr/local/src/github.com/foswiki/core/lib/Foswiki/Form.pm line 262
   Foswiki::Form::_parseFormDefinition('Foswiki::Plugins::MongoDBPlugin::Meta=HASH(0x2be3a60)') called at /usr/local/src/github.com/foswiki/core/lib/Foswiki/Form.pm line 121
   Foswiki::Form::new('Foswiki::Form', 'Foswiki=HASH(0x2bf8e80)', 'System', 'UserForm') called at /usr/local/src/github.com/foswiki/core/test/unit/FormDefTests.pm line 344
   FormDefTests::test_Item10987_formObjClass('FormDefTests=HASH(0x1968030)') called at /usr/local/src/github.com/foswiki/core/lib/Unit/TestRunner.pm line 383
   Unit::TestRunner::__ANON__() called at /usr/local/src/github.com/foswiki/core/lib/CPAN/lib/Error.pm line 379
   eval {...} called at /usr/local/src/github.com/foswiki/core/lib/CPAN/lib/Error.pm line 371
   Error::subs::try('CODE(0x2a51950)', 'HASH(0x2bc1bc8)') called at /usr/local/src/github.com/foswiki/core/lib/Unit/TestRunner.pm line 402
   Unit::TestRunner::runOne('FormDefTests=HASH(0x1968030)', 'FormDefTests', 'test_Item10987_formObjClass') called at /usr/local/src/github.com/foswiki/core/lib/Unit/TestRunner.pm line 137
   Unit::TestRunner::start('Unit::TestRunner=HASH(0x1626db0)', 'FormDefTests::test_Item10987_formObjClass') called

-- PaulHarvey - 17 Aug 2011

did the fix I made to resolve the unit test fix it?

the core problem is that i thought Foswiki::Form objects were a promotion of an existing Meta obj, whereas your use clearly shows me i was being very forgetful.

-- SvenDowideit - 17 Aug 2011

Yep, works good. And my "fix" caused huge performance problems... bigger than I expected. Anyway, your fix seems to be doing the job

-- PaulHarvey - 18 Aug 2011

Commenting is disabled while not logged in