Reloading base throws exception in Log.cfc

[doug_smith]

This is a strange one. (I was trying to work on the BaseEndpoint change in #776, and got stuck for a long while trying to debug this.) (Adobe CF9, Mach-II trunk version 2798.)

Using the latest BER in a simple app, I frequently, though not always, get an exception during base reload. The exception is typically this with a different key in every case.

Exception:

Element 690A54784FACC6DD06E3D45D396E0BB6 is undefined in a CFML structure referenced as part of an expression. 

Stack trace:

mach_ii_1_9_0_trunk\logging\Log.cfc:174
mach_ii_1_9_0_trunk\framework\EventContext.cfc:740
mach_ii_1_9_0_trunk\framework\commands\RedirectCommand.cfc:114
mach_ii_1_9_0_trunk\framework\EventHandler.cfc:91
mach_ii_1_9_0_trunk\framework\RequestHandler.cfc:464
...

The problem doesn't happen in the build of MachII 1.9 we're running in production, which is mostly based on your svn rev 2586, with the addition of patches we have written and submitted to your codebase.

The problem always happens in a loop similar to this:

<cfloop collection="#variables.logAdapters#" item="key">
	<cfset variables.logAdapters[key].info(channel, arguments.message) />
</cfloop>

The key exists in the loop, but when the call to "...info(...)" is attempted, the key is no longer in the logAdapters struct.

There appears to be a race condition during reload where the logAdapter object is being removed/dereferenced, yet the key still remains in the logAdapters struct. It's tough to track down since the logAdapters struct in the Log.cfc references the same struct as is used in the LogFactory?, among other things.

Could this be related to #726?

[peterjfarrell]

Doug, I'm thinking it probably does relate to #726. I am unable to reproduce the issue here (on ACF8 / Apache / Tomcat), however looking at the LoggerManager we add the log adapter to the LogFactory during configure() but don't remove it when deconfigure() is called. I'm going to add a fix to the BER and let me know if it fixes the issue.

Also, I found an unrelated bug having to do with the AppLoader.deconfigure() stuff in #726 having to do with threading. However, I don't think it has to do with this issue.

A commit coming soon that may fix this issue.

[peterjfarrell]

(In [2800]) refs #795

[peterjfarrell]

@Doug, check out the BER and see if removing the log adapter from the log factory during deconfigure() fixes the issue. Sounds like ACF9 changes something having to do with structs because I can't reproduce this issue on ACF8. Let me know how it works out.

Do you by chance have more than one LoggingProperty setup in your test application base or module? I'm seeing a possible other issue which I just committed a fix for.

[doug_smith]

Hi Peter,

Unfortunately, it does still happen. It sometimes takes up to 20 reloads, other times only 3-4, but it happens in the same way as before.

CF9 does change the way Structs behave. I'm wondering if there may be some kind of issue that happens when an object is in a struct, and also referenced elsewhere. If that object gets dereferenced, but the key is still in the struct, it's possible that when you ask the struct for its keys, something internal checks to see that the value has been dereferenced and deletes the key. The reason I think this is that when I added a <cfdump /> just before the loop I referenced earlier, <cfdump /> itself failed with a similar missing key exception.

I do have two LoggingProperties?: one in the base, and the one that comes built-in to the dashboard module.

[peterjfarrell]

Hi Doug, If ACF9 changed behavior, this is serious business and bad bug in the engine. I guess I'll have to pull down an ACF9 copy and test things out. Can you confirm that you have all the updates for ACF9 and running 9.01?

I'm wondering if it has to do with any of this:

http://boncode.blogspot.com/2011/01/cf-explicit-undefined-in-coldfusion-9.html

[peterjfarrell]

Doug, can you try something for me? Would you wrap a try/catch around that offending section in the Log.cfc and dump out variables.logAdapters to see what's in there?

[doug_smith]

Yes, I'm running ACF9.01: (9,0,1,274733). When I dump variables.logAdapters in the catch, it's an empty struct. I agree, it felt like a bug when I was looking at it yesterday.

[doug_smith]

I have created a test app that includes ACF 9.0.1 with Mach-II 1.9 BER (svn rev 2828). You can download the app here:

 http://dl.dropbox.com/u/12411108/machii_19_reload_bug_test.zip

There is a selenium test that reloads the base app ~30 times. With ACF 9.0.1 it fails intermittently. With the previous version of Mach-II 1.9 that we are running in production (essentially build 2669 with minor patches), it never fails. Interestingly, running ACF 8.0.1 (8,0,1,195765) and the latest BER, it never fails either.

The following straight CF code always throws an exception on the 10th line in ACF 8 or 9, and somewhat describes what might be intermittently happening:

---

<cfset local.stc = StructNew?() /> <cfset local.stc.one = "uno" /> <cfset local.stc.two = "dos" /> <cfset local.stc.three = getUndefined() />

<cfoutput><p>Items in struct: #StructCount?(local.stc)#</p></cfoutput> <cfoutput><p>Has "three"? #StructKeyExists?(local.stc, "three")#</p></cfoutput>

<cfloop collection="#local.stc#" item="key">

<cfset local.title = local.stc[key].toString() /> <cfoutput><p>#local.title#</p></cfoutput>

</cfloop>

<cffunction name="getUndefined" returntype="void">

<cfreturn />

</cffunction>

---

If you run this code, you'll see that CF thinks there are three items in the struct, but if you call StructKeyExists? on "three", it'll answer "NO". Then, when iterating over the struct, it will iterate three times, then throw an exception when trying to read the value of the key "three" from the struct.

The errors that are being thrown intermittently during base reloads with the latest Mach-II codebase are similar to this. However, it's more weird, because in this latter case (Mach-II 1.9 v2828 on ACF9.0.1) the key seems to get deleted in the loop. For example, if I do a StructCount?(variables.logAdapters) before the exception, then again after the exception in a catch block, the count in the exception block is one less than the one before. This doesn't happen in the code snippet above -- in CF8 or CF9, the StructCount?() stays the same.

This is long, but I've been trying to figure it out for a while here and thought I'd share as much info as I have. Hopefully we can either find a workaround or talk Adobe into fixing the bug, if we can truly confirm it.

[doug.smith]

Any updates on this one? Thoughts about possible fixes? I'm tempted to just put in a check for StructKeyExists?() within the loops that fail and move forward so we can start using the latest release. However, that may just be a band-aid.

[peterjfarrell]

@Doug, I looked into this and it definitely is a bug in AC9. I'm not sure how to get this to Adobe support. Do you guys have a support contract?

[doug_smith]

We don't have a support contract. It is unlikely we have enough pull to get movement on it.

Do you think it's worth putting the structKeyExists() check within some the loops that fail during reload?

[peterjfarrell]

@Doug, I've asked on CFGURU to see if there is a good way to get this to the attention of Adobe Support. I have logged a ticket (which will probably be ignored):

 http://cfbugs.adobe.com/cfbugreport/flexbugui/cfbugtracker/main.html?#bugId=87084

I'm thinking as a workaround we add a try/catch to ignore the issue so we aren't socked with having to check if the key exists (which works like 99.9999999999999999999% of the time).

[doug_smith]

@Peter, thanks for adding this bug and getting back to us on this. I like the try/catch idea as long as the base reload will fully succeed if the exception is thrown. Where would you put that? Do you have time to add it? If not, if you point me in the right direction, I'll look at it.

[peterjfarrell]

@Doug, I'm researching workarounds right now. I'm not sure I'm a fan of the try/catch idea I originally suggested. I'm doing some more research and testing but I'm leaning in a different direction (a new CFC called LogAdapterManager). I believe this issue has to do with something with structs being referenced by ref in other structs -- a CFC would centralize this since we're not sharing a struct -- there doesn't appear to be issues with sharing CFCs by ref ;-)

[doug_smith]

That sounds good, @Peter. Thank you for looking into it!

[doug_smith]

@Peter, just to know how to plan ... any thoughts about timing on this one? Should we go with a try/catch for now until Adobe possibly fixes the bug?

[matt_woodward]

 https://github.com/Mach-II/Mach-II-Framework/issues/10