ObjectReference Broken Pointer Bug

Introduction

These are my (taleden's) logs and notes regarding the ObjectReference broken pointer bug, whose symptom is the log error "no native object bound to the script object, or object is of incorrect type". On 2013-10-25 I posted the following to Bethesda's CreationKit forum:

The folks at the Unofficial Skyrim Patch (and probably lots of other modders) have been struggling for months with ObjectReference pointers that go bad, and I think it may actually be a bug in the Papyrus scripting engine, or the game engine, or maybe in the interface between the two.

The symptom of this bug is an error in the debug log that reads "Unable to call [Method] - no native object bound to the script object, or object is of incorrect type". This happens even when the pointer on which the method is being called is not None; when that is the case, the error instead says "Cannot call [Method] on a None object, aborting function call".

I believe the bug arises whenever an object reference has an extra script attached to it (extending the ObjectReference script), and that item is moved from a container/inventory into the world, while it also has a persistent reference.

Here's a short example that illustrates the problem:

Form item = Game.GetForm(0x10AA19) ; Silver Sword
ObjectReference ref = Game.GetPlayer().PlaceAtMe(item)
Debug.Trace(ref+" GetFormID()="+ref.GetFormID()+", SilverPerk="+(ref as SilverSwordScript).SilverPerk)
Game.GetPlayer().AddItem(ref)
Debug.Trace(ref+" GetFormID()="+ref.GetFormID()+", SilverPerk="+(ref as SilverSwordScript).SilverPerk)
ref = Game.GetPlayer().DropObject(item)
Debug.Trace(ref+" GetFormID()="+ref.GetFormID()+", SilverPerk="+(ref as SilverSwordScript).SilverPerk) ; line 33

The log then reads:

 [10/25/2013 - 02:10:58PM] [SilverSwordScript < (FF000898)>] GetFormID()=-16775016, SilverPerk=[Perk < (0010D685)>]
 [10/25/2013 - 02:10:58PM] [SilverSwordScript <Item 3 in container  (00000014)>] GetFormID()=-16775016, SilverPerk=[Perk < (0010D685)>]
 [10/25/2013 - 02:10:58PM] error: Unable to call GetFormID - no native object bound to the script object, or object is of incorrect type
 stack:
     [Item 3 in container  (00000014)].SilverSwordScript.GetFormID() - "<native>" Line ?
     [alias PlayerRef on quest TestQuest (0A000D6A)].TestQuest_PlayerRef_Script.OnUpdate() - "TestQuest_PlayerRef_Script.psc" Line 33
 [10/25/2013 - 02:10:58PM] warning: Assigning None to a non-object variable named "::temp6"
 stack:
     [alias PlayerRef on quest TestQuest (0A000D6A)].TestQuest_PlayerRef_Script.OnUpdate() - "TestQuest_PlayerRef_Script.psc" Line 33
 [10/25/2013 - 02:10:58PM] [SilverSwordScript <Item 3 in container  (00000014)>] GetFormID()=0, SilverPerk=[Perk < (0010D685)>]

Note that the item must have a script either on its base form (as the Silver Sword does here) or on the particular cell-placed reference that the player picks up (such as Ghostblade and Zephyr), and the reference must be persistent at the moment it is dropped back into the world (as is done here by having the PlaceAtMe()-created reference stored in a running script variable at the time DropObject() is called; PlaceAtMe() can also force the created reference to be persistent, but the result is the same in this test).

When these conditions are met, then any ObjectReference pointer which refers to the item is prone to break, as seen here in the pointer returned from DropObject(). When a pointer breaks in this way, then no native methods can be called on it (such as GetFormID()), however methods which are fully defined in Papyrus on the attached script or any of its parent scripts can still be called normally (such as the implicit SilverPerk property getter function). This implies that the Papyrus script object is no longer correctly linked to its corresponding game engine object, so when it tries to call into the game engine to evaluate a native method, the engine reports that it has no (compatible) object to run it on.

Note that the bug is not limited to DropObject(), that's just the quickest way to invoke it. For example, the player can drop the item manually, and any (persistent) ObjectReference pointer which was previously received and cached in OnItemAdded(), OnItemEquipped() etc. will immediately become broken. Or, the player can drop the item while it is equipped, and then OnItemUnequipped() receives a broken pointer, but OnItemRemoved() receives a functional pointer. The key elements are the persistent object reference, and the extra attached script.

I have a lot more log data if anyone is interested, plus an object reference testing mod that I've been using to diagnose this issue. Apologies also if this has been reported and discussed before, I did a search and only found other players with the same log error, but no investigation or explanation.

This article contains the log data mentioned above.

Testing Methodology

In order to understand these logs, here is the testing methodology that I used to generate them.

I made a testing mod which uses a quest's reference alias on the player to monitor item-related events and analyze the object reference pointers they each receive from the engine. To keep the test cases as clean as possible, the mod also defines six custom items which are all clones of the Iron Sword, with some variation to mimic a particular test case:

• Test Sword (NP, NS)
• Test Sword (NP, FS)
• Test Sword (P, NS)
• Test Sword (P, FS)
• Test Sword (P, AS)
• Test Sword (P, RS)

The tags on each item identify the properties of each test case:

• "NP" means non-persistent, so these two items are given to the player on game load using AddItem() so that they do not have a persistent reference.
• The "P" items (except for "P, RS") are granted by the test quest as created reference aliases so that they are persistent.
• "NS" means non-scripted, so these forms have no extra scripts attached anywhere.
• "FS" means form-scripted, so these base weapon forms have scripts attached which extend ObjectReference.
• "AS" means alias-scripted, so the quest reference alias which creates this item also attaches a script which extends ReferenceAlias.
• The "P, RS" item is placed directly in the qasmoke cell so that it has a persistent world-placed reference, and so that a script can be attached to that placed reference in the CK.

There is no "NP, RS" test case because I don't think it's possible to attach a script via reference without that reference also being persistent (i.e. placed in a cell in the CK). Likewise for "NP, AS", as soon as a quest fills a reference into an alias in order to put an alias script on it, my understanding is that the reference also becomes persistent.

The mod also has a menu control item, and the first time this is activated, the player alias script starts listening for item events (OnItemAdded(), OnItemRemoved(), OnObjectEquipped() and OnObjectUnequipped()). The first time one of these events fires, the base form involved (which should be one of the test items above) is set as the form to be tracked, so that future events are only handled if they involve the same base item. The ObjectReference pointers provided to each event handler are then cached in six different slots, corresponding to six ways they can be acquired:

• "AW": OnItemAdded() from the world (akSrcContainer == None)
• "RW": OnItemRemoved() to the world (akDestContainer == None)
• "AC": OnItemAdded() from a container (akSrcContainer != None)
• "RC": OnItemRemoved() to a container (akDestContainer != None)
• "Eq": OnObjectEquipped()
• "Un": OnObjectUnequipped()

Each cached pointer is filled in the first time each event fires and receives an ObjectReference pointer other than None. On each event, a log message is written that reports the properties of the ObjectReference pointer received by the event: if it is broken (so not even GetFormID() can be called on it without error), the log just shows "(broken)"; otherwise, the log prints the ObjectReference's own FormID, the FormIDs returned by GetBaseObject() and GetParentCell(), and the flags returned by Is3DLoaded() and IsDeleted(). This is followed by the pointer itself cast as a string (which reveals what script Papyrus thinks it represents) and a list of flags indicating whether the pointer compares as equal to any of the previously observed and cached ObjectReference pointers, or whether the received pointer was stored in any of those slots.

Meanwhile, a 10s OnUpdate() loop periodically tests each cached ObjectReference pointer and reports "-" if it is still set to None, "+" if it is set and remains functional (i.e. GetFormID() can be called without the "object is of incorrect type" error), or "!" if it has become broken (GetFormID() appears to return 0, which corresponds with the log error).

Once a form is being tracked, the menu item can also be used to call Player.DropObject(), Player.AddItem(), ref.MoveTo() and ref.Reset(), using the base form or any of the cached ObjectReferences. When calling DropObject(), the return value is also reported and compared to the cached ObjectReference pointers.

Test cases

non-persistent, non-scripted

The log begins while the test item is in inventory but not equipped:

[10/22/2013 - 03:10:58PM] ready to track references
[10/22/2013 - 03:11:03PM] now tracking Test Sword (NP, NS) '[WEAPON < (0A000D62)>]'
[10/22/2013 - 03:11:03PM] OnItemAdded(world): [None]
[10/22/2013 - 03:11:10PM] OnObjectEquipped(): [None]
[10/22/2013 - 03:11:13PM] OnObjectUnequipped(): [None]
[10/22/2013 - 03:11:15PM] OnUpdate(): AW:- RW:- AC:- RC:- Eq:- Un:-
[10/22/2013 - 03:11:19PM] OnItemRemoved(Container): [None]
[10/22/2013 - 03:11:26PM] OnItemAdded(Container): [None]
[10/22/2013 - 03:11:32PM] OnItemRemoved(world): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ->RW

At first, since the item does not have a persistent reference, the event handlers are not given any ObjectReference pointer at all; this is expected according to the CK documentation. But as also noted in the CK wiki, OnItemRemoved() is different: "If a non-persistent item is dropped from inventory into the world the generated reference is received." Since this pointer is immediately cached in a script variable by the test mod, the reference becomes persistent and now all the other events start receiving it as well:

[10/22/2013 - 03:11:37PM] OnItemAdded(world): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ->AW ==RW
[10/22/2013 - 03:11:42PM] OnUpdate(): AW:+ RW:+ AC:- RC:- Eq:- Un:-
[10/22/2013 - 03:11:52PM] OnObjectEquipped(): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ->Eq
[10/22/2013 - 03:11:59PM] OnObjectUnequipped(): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==Eq ->Un
[10/22/2013 - 03:12:06PM] OnItemRemoved(world): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==Eq ==Un
[10/22/2013 - 03:12:11PM] OnUpdate(): AW:+ RW:+ AC:- RC:- Eq:+ Un:+
[10/22/2013 - 03:12:13PM] OnItemAdded(world): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==Eq ==Un
[10/22/2013 - 03:12:21PM] OnUpdate(): AW:+ RW:+ AC:- RC:- Eq:+ Un:+
[10/22/2013 - 03:12:26PM] OnItemRemoved(Container): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ->RC ==Eq ==Un
[10/22/2013 - 03:12:45PM] OnItemAdded(Container): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ->AC ==RC ==Eq ==Un
[10/22/2013 - 03:12:52PM] OnObjectEquipped(): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:13:02PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:13:07PM] OnObjectUnequipped(): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un

We can see each cache slot get filled in one by one as each event is first triggered with an ObjectReference pointer. Since this item is not scripted, all of those received ObjectReference pointers continue to identify themselves as '[ObjectReference <...>]' and compare equal to each other, and none of the cached pointers ever break, even after the item is picked up and dropped several times, both manually by the player and via DropObject():

[10/22/2013 - 03:13:08PM] OnItemRemoved(world): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:13:17PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:13:25PM] OnItemAdded(world): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:13:27PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:13:33PM] OnItemRemoved(world): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:13:55PM] calling player.AddItem([AW ref])
[10/22/2013 - 03:13:55PM] OnItemAdded(world): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:14:04PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:14:09PM] OnObjectEquipped(): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:14:15PM] OnObjectUnequipped(): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:14:22PM] OnItemRemoved(world): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:14:26PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:14:26PM] OnItemAdded(world): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:14:49PM] calling player.DropObject([form])
[10/22/2013 - 03:14:49PM] OnItemRemoved(world): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:14:49PM] DropObject(): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:14:52PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:14:55PM] OnItemAdded(world): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:15:02PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:15:09PM] OnObjectEquipped(): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:15:27PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:15:39PM] calling player.DropObject([form])
[10/22/2013 - 03:15:39PM] OnObjectUnequipped(): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:15:39PM] OnObjectUnequipped(): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:15:39PM] OnItemRemoved(world): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:15:39PM] DropObject(): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:15:47PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:15:57PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:16:07PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:16:08PM] OnItemAdded(world): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:16:20PM] calling player.DropObject([form])
[10/22/2013 - 03:16:20PM] DropObject(): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:16:20PM] OnItemRemoved(world): FF000898 (base=A000D62 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:16:23PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:16:43PM] calling [ObjectReference < (FF000898)>].Reset()
note: it vanished off the ground at this point
[10/22/2013 - 03:16:45PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:16:56PM] calling player.AddItem([AW ref])
[10/22/2013 - 03:16:56PM] OnItemAdded(world): FF000898 (base=A000D62 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW ==RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:17:09PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+

There are a few interesting things to note here, including several hints about how the game engine handles object references natively. I suspect that whenever an item is inside a container (or actor inventory), it actually has no ObjectReference, or perhaps it is just given a different reference (and perhaps this is why we sometimes see (ref As String) return things like "<Item 1 in container (00000014)>"). Here are some clues that support this interpretation:

• None of the item events normally receive an ObjectReference pointer argument if the item is still in a container or inventory, unless the reference is persistent. If a reference exists at this time, and the event handlers are already equipped to receive it, why does the engine not provide it to the handlers unless it's persistent or the item is dropped to the world?
• Every ObjectReference observed by Papyrus reports IsDeleted()==TRUE whenever the corresponding item is not on the ground, even if the pointer was just received by an event. What sense does it make for the engine to pass deleted references into Papyrus event handlers, if a non-deleted reference exists for the same item?
• The CK wiki documentation for OnItemRemoved() refers to "the generated reference". If a non-persistent item in inventory has an ObjectReference of any kind, why is one "generated" when it is dropped to the world?
• When the player drops items to the world that do not already have persistent references, the FormID numbering of the observed object references are not consistent. Try it: drop two non-persistent items and then click them each in the console to see their reference FormIDs. Now pick both up and drop them again in the opposite order: the engine recycles these reference FormIDs and re-uses them in the order that items are dropped, so the actual items end up with each other's previous reference FormIDs, rather than maintaining one consistent reference FormID for each distinct item.

These are all just curiosities for the moment, but as we get into the problematic edge cases, some of these quirks may help explain what's going on.

non-persistent, form-scripted

Again, the item starts in inventory but not equipped:

[10/22/2013 - 03:37:44PM] ready to track references
[10/22/2013 - 03:37:58PM] now tracking Test Sword (NP, FS) '[WEAPON < (0A000D63)>]'
[10/22/2013 - 03:37:58PM] OnObjectEquipped(): [None]
[10/22/2013 - 03:38:03PM] OnObjectUnequipped(): [None]
[10/22/2013 - 03:38:17PM] OnObjectEquipped(): [None]
[10/22/2013 - 03:38:21PM] OnObjectUnequipped(): [None]
[10/22/2013 - 03:38:22PM] OnItemRemoved(Container): [None]
[10/22/2013 - 03:38:32PM] OnItemAdded(Container): [None]
[10/22/2013 - 03:38:40PM] OnItemRemoved(world): FF000898 (base=A000D63 cell=32Ae7 3d=1 del=0) '[ORT_FormScript < (FF000898)>]' ->RW
[10/22/2013 - 03:38:46PM] OnUpdate(): AW:- RW:+ AC:- RC:- Eq:- Un:-

Once again, since the reference is not initially persistent, none of the events receive an ObjectReference pointer until OnItemRemoved() when it is first dropped to the world. And once again when that generated reference is cached (and thus made persistent), then the other events start receiving pointers as the item is picked up, equipped, shuffled to containers, etc:

[10/22/2013 - 03:38:51PM] OnItemAdded(world): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ->AW !=RW
[10/22/2013 - 03:38:56PM] OnUpdate(): AW:+ RW:+ AC:- RC:- Eq:- Un:-
[10/22/2013 - 03:39:00PM] OnObjectEquipped(): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW !=RW ->Eq
[10/22/2013 - 03:39:10PM] OnUpdate(): AW:+ RW:+ AC:- RC:- Eq:+ Un:-
[10/22/2013 - 03:39:14PM] OnObjectUnequipped(): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW !=RW ==Eq ->Un
[10/22/2013 - 03:39:24PM] OnUpdate(): AW:+ RW:+ AC:- RC:- Eq:+ Un:+
[10/22/2013 - 03:39:28PM] OnItemRemoved(Container): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW !=RW ->RC ==Eq ==Un
[10/22/2013 - 03:39:39PM] OnUpdate(): AW:+ RW:+ AC:- RC:+ Eq:+ Un:+
[10/22/2013 - 03:39:44PM] OnItemAdded(Container): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW !=RW ->AC ==RC ==Eq ==Un
[10/22/2013 - 03:39:52PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:39:57PM] OnObjectEquipped(): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW !=RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:40:05PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:40:09PM] OnObjectUnequipped(): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW !=RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:40:18PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:40:26PM] print [AW ref]: FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' ==AW !=RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:40:30PM] print [RW ref]: FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ORT_FormScript <Item 2 in container  (00000014)>]' !=AW ==RW !=AC !=RC !=Eq !=Un

But we can already see some differences here. First, OnItemRemoved() always receives a pointer which identifies itself as '[ORT_FormScript <...>]' (which is the name of the form attached to this item's base weapon form; ORT is ObjRefTest, my testing mod) rather than '[ObjectReference <...>]'. The other events receive more normal-looking pointers, but notice that they never compare as equal to the one that we initially got in OnItemRemoved(), although they do all compare equal to each other. Notice also that when the item is back in the player's inventory, re-printing the pointer that we got from OnItemRemoved() gives a different result than it did initially, while the item was on the ground: instead of '[ORT_FormScript < (FF000898)>]', it is now '[ORT_FormScript <Item 2 in container (00000014)>]'. The pointer we cached from OnItemAdded() remains the same as it was.

So far this is only a little strange, but not a huge problem since at least all of the cached reference pointers continue to work. But look what happens when the item is dropped to the world a second time, while it is already persistent:

[10/22/2013 - 03:40:33PM] OnItemRemoved(world): FF000898 (base=A000D63 cell=32Ae7 3d=1 del=0) '[ORT_FormScript < (FF000898)>]' !=AW ==RW !=AC !=RC !=Eq !=Un
[10/22/2013 - 03:40:35PM] error: Unable to call GetFormID - no native object bound to the script object, or object is of incorrect type
stack:
    [None].ObjectReference.GetFormID() - "<native>" Line ?
    [alias PlayerRef on quest ORT_Q_Main (0A000D6A)].ORT_Q_Main_RA_PlayerRef_Script.RefToStatusFlag() - "ORT_Q_Main_RA_PlayerRef_Script.psc" Line 243
    [alias PlayerRef on quest ORT_Q_Main (0A000D6A)].ORT_Q_Main_RA_PlayerRef_Script.OnUpdate() - "ORT_Q_Main_RA_PlayerRef_Script.psc" Line 159
[10/22/2013 - 03:40:35PM] warning: Assigning None to a non-object variable named "::temp50"
stack:
    [alias PlayerRef on quest ORT_Q_Main (0A000D6A)].ORT_Q_Main_RA_PlayerRef_Script.RefToStatusFlag() - "ORT_Q_Main_RA_PlayerRef_Script.psc" Line 243
    [alias PlayerRef on quest ORT_Q_Main (0A000D6A)].ORT_Q_Main_RA_PlayerRef_Script.OnUpdate() - "ORT_Q_Main_RA_PlayerRef_Script.psc" Line 159
...errors...
[10/22/2013 - 03:40:35PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:40:39PM] print [AW ref]: (broken) '[ObjectReference <None>]' ==AW !=RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:40:43PM] print [RW ref]: FF000898 (base=A000D63 cell=32Ae7 3d=1 del=0) '[ORT_FormScript < (FF000898)>]' !=AW ==RW !=AC !=RC !=Eq !=Un

OnItemRemoved() receives a pointer which compares equal to the original RW pointer, but on the next OnUpdate() test, all of the other cached pointers have become broken (see all the "!" tags). I've only included one set of error messages and stack traces to look at; for the sake of readability further errors of this type have been replaced with "...", but it's the same every time (and the pair of errors repeats many times per OnUpdate(), once for each cached pointer that is tested and found to be broken). And it's no wonder they're broken: re-printing the stored AW pointer now reads '[ObjectReference <None>]' which definitely isn't right.

So now the item is on the ground, and our funny-looking RW pointer with the attached script name still works, but all of our other cached ObjectReference pointers are broken. Fortunately, when we pick the item up again and then move it around in inventory, those events continue to receive functional ObjectReference pointers:

[10/22/2013 - 03:40:48PM] OnItemAdded(world): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' !=AW !=RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:40:52PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:40:58PM] OnObjectEquipped(): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' !=AW !=RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:41:06PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:41:16PM] OnObjectUnequipped(): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' !=AW !=RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:41:26PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:41:30PM] OnItemRemoved(Container): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' !=AW !=RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:41:40PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:41:45PM] OnItemAdded(Container): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' !=AW !=RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:41:52PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:42:23PM] OnItemRemoved(world): FF000898 (base=A000D63 cell=32Ae7 3d=1 del=0) '[ORT_FormScript < (FF000898)>]' !=AW ==RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:42:31PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:42:34PM] OnItemAdded(world): FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF000898)>]' !=AW !=RW !=AC !=RC !=Eq !=Un

The received pointers do not compare equal to the ones originally received and cached, but this is no surprise since those cached pointers are now broken and call themselves '[ObjectReference <None>]', while the newly provided pointers work and look normal. We can even drop the item to the ground a third time, and that pointer also remains consistent with the first RW pointer.

Next we try force-dropping the item with DropObject():

...errors...
[10/22/2013 - 03:43:15PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:43:19PM] print [RW ref]: FF000898 (base=A000D63 cell=32Ae7 3d=0 del=1) '[ORT_FormScript <Item 2 in container  (00000014)>]' !=AW ==RW !=AC !=RC !=Eq !=Un
[10/22/2013 - 03:43:22PM] calling player.DropObject([form])
...errors...
[10/22/2013 - 03:43:22PM] DropObject(): (broken) '[ORT_FormScript <Item 2 in container  (00000014)>]' !=AW ==RW !=AC !=RC !=Eq !=Un
[10/22/2013 - 03:43:22PM] OnItemRemoved(world): FF000898 (base=A000D63 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' !=AW !=RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:43:27PM] print [RW ref]: (broken) '[ORT_FormScript <Item 2 in container  (00000014)>]' !=AW ==RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:43:29PM] OnUpdate(): AW:! RW:! AC:! RC:! Eq:! Un:!

And lo, the reference returned directly from DropObject() is broken. This is a first; until this point, all of the newly-provided reference pointers have worked, it was just our cached copies of old pointers that broke, but here we have a fresh pointer straight from the engine which is immediately broken and unusable. But there's a clue about why this might be: the broken pointer returned by DropObject() calls itself '[ORT_FormScript <Item 2 in container (00000014)>]', which is what our old RW pointer called itself while the item was in inventory instead of on the ground. So it seems that perhaps DropObject() has given us an inventory version of the item's reference, which was valid when DropObject() found it in the player's inventory, but is no longer valid as soon as the item is dropped.

The good news is that when OnItemRemoved() fires as a result of the DropObject(), it still gets a functional ObjectReference pointer. However, that pointer identifies itself as '[ObjectReference <...>]' instead of the '[ORT_FormScript <...>]' that we've always seen before in OnItemRemoved(), which is a little strange. It also no longer compares equal to the cached RW pointer, which had always stayed consistent until now, but this is not surprising because the cached RW pointer has also just become broken. And yet, it has broken in a different way than the other cached pointers: instead of identifying itself as '[... <None>]', it still says '[... <Item 2 in container (00000014)>]' just like it did while the item was in inventory, and just like the broken pointer we got back from DropObject().

So now that all of the cached pointers are broken, what happens when we pick the item up again?

[10/22/2013 - 03:43:39PM] OnItemAdded(world): [None]
...errors...
[10/22/2013 - 03:43:39PM] OnUpdate(): AW:! RW:! AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:43:47PM] OnObjectEquipped(): [None]
[10/22/2013 - 03:43:54PM] OnObjectUnequipped(): [None]
...errors...
[10/22/2013 - 03:43:57PM] OnUpdate(): AW:! RW:! AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:44:03PM] OnItemRemoved(world): FF000898 (base=A000D63 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF000898)>]' !=AW !=RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:44:15PM] OnUpdate(): AW:! RW:! AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:44:18PM] OnItemAdded(world): [None]
[10/22/2013 - 03:44:25PM] OnItemRemoved(Container): [None]
...errors...
[10/22/2013 - 03:44:29PM] OnUpdate(): AW:! RW:! AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:44:36PM] OnItemAdded(Container): [None]
...errors...
[10/22/2013 - 03:44:42PM] OnUpdate(): AW:! RW:! AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:44:46PM] OnObjectEquipped(): [None]
...errors...
[10/22/2013 - 03:44:55PM] OnUpdate(): AW:! RW:! AC:! RC:! Eq:! Un:!

Suddenly we're back to square one, and none of the events receive an ObjectReference pointer except for OnItemRemoved(). That suggests that the item's reference is no longer persistent, which makes a kind of sense: the cached RW pointer was the last one that still worked, and once it breaks, then none of them are really pointing to the item any more. That in turn means the item has no ObjectReference pointers held in script variables, which makes it non-persistent again. Only this time, since the test mod has already filled in all of its cached pointers (even though they're now broken), it does not cache the pointer given to OnItemRemoved(), so the reference does not become persistent again. We can pick it up and drop it repeatedly, and the only event which gets a pointer is OnItemRemoved().

To drive the point home, I dropped a few unrelated items to the ground first, and then dropped the test item again:

[10/22/2013 - 03:44:59PM] OnObjectUnequipped(): [None]
[10/22/2013 - 03:44:59PM] OnItemRemoved(world): FF0008Be (base=A000D63 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF0008BE)>]' !=AW !=RW !=AC !=RC !=Eq !=Un
[10/22/2013 - 03:45:08PM] error: Unable to call GetFormID - no native object bound to the script object, or object is of incorrect type
...errors...
[10/22/2013 - 03:45:08PM] OnUpdate(): AW:! RW:! AC:! RC:! Eq:! Un:!

Sure enough, the pointer received by this last OnItemRemoved() has a different FormID (FF0008BE) than all of the other ObjectReference pointers we've seen this whole time (FF000898).

So what happens if we start re-caching observed pointers? The process starts all over again:

[10/22/2013 - 03:49:27PM] set recaching = TRUE
[10/22/2013 - 03:49:34PM] OnItemAdded(world): [None]
[10/22/2013 - 03:49:53PM] OnItemRemoved(world): FF0008Be (base=A000D63 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF0008BE)>]' !=AW ->RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:49:55PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:49:59PM] OnItemAdded(world): FF0008Be (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF0008BE)>]' ->AW !=RW !=AC !=RC !=Eq !=Un
[10/22/2013 - 03:50:07PM] OnObjectEquipped(): FF0008Be (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF0008BE)>]' ==AW !=RW !=AC !=RC ->Eq !=Un
[10/22/2013 - 03:50:09PM] OnObjectUnequipped(): FF0008Be (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF0008BE)>]' ==AW !=RW !=AC !=RC ==Eq ->Un
[10/22/2013 - 03:50:16PM] OnItemRemoved(Container): FF0008Be (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF0008BE)>]' ==AW !=RW !=AC ->RC ==Eq ==Un
[10/22/2013 - 03:50:18PM] OnItemAdded(Container): FF0008Be (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF0008BE)>]' ==AW !=RW ->AC ==RC ==Eq ==Un
[10/22/2013 - 03:50:19PM] OnUpdate(): AW:+ RW:+ AC:+ RC:+ Eq:+ Un:+
[10/22/2013 - 03:50:30PM] print [AW ref]: FF0008Be (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF0008BE)>]' ==AW !=RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:50:33PM] print [RW ref]: FF0008Be (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference <Item 2 in container  (00000014)>]' !=AW ==RW !=AC !=RC !=Eq !=Un

Just as before, we fill in all the cached pointers and they all look correct and compare equal to each other, except for the RW pointer. But unlike before, that RW pointer is calling itself '[ObjectReference <...>]' instead of the item's attached script. This might give hope that the broken pointer problem could be avoided this time, since Papyrus doesn't seem to have any confusion about what class the pointer is, but of course we're not so lucky:

[10/22/2013 - 03:50:39PM] OnItemRemoved(world): FF0008Be (base=A000D63 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF0008BE)>]' !=AW ==RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:50:51PM] print [AW ref]: (broken) '[ObjectReference <None>]' ==AW !=RW ==AC ==RC ==Eq ==Un
[10/22/2013 - 03:50:54PM] print [RW ref]: FF0008Be (base=A000D63 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF0008BE)>]' !=AW ==RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:50:57PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:51:02PM] OnItemAdded(world): FF0008Be (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF0008BE)>]' ->AW !=RW !=AC !=RC !=Eq !=Un
[10/22/2013 - 03:51:10PM] OnItemRemoved(world): FF0008Be (base=A000D63 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF0008BE)>]' !=AW ==RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:51:15PM] OnUpdate(): AW:! RW:+ AC:! RC:! Eq:! Un:!

Just as before, dropping the item again breaks all the non-RW pointers, although we can at least still drop it multiple times without losing the RW pointer, and each event does still receive a functional pointer when it is triggered. But again, DropObject() mucks it all up:

[10/22/2013 - 03:51:17PM] OnItemAdded(world): FF0008Be (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference < (FF0008BE)>]' ->AW !=RW !=AC !=RC !=Eq !=Un
[10/22/2013 - 03:51:48PM] calling player.DropObject([form])
...errors...
[10/22/2013 - 03:51:48PM] DropObject(): (broken) '[ObjectReference <Item 2 in container  (00000014)>]' !=AW ==RW !=AC !=RC !=Eq !=Un
[10/22/2013 - 03:51:48PM] OnItemRemoved(world): FF0008Be (base=A000D63 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF0008BE)>]' ==AW ->RW !=AC !=RC !=Eq !=Un
[10/22/2013 - 03:51:57PM] print [RW ref]: FF0008Be (base=A000D63 cell=32Ae7 3d=1 del=0) '[ObjectReference < (FF0008BE)>]' ==AW ==RW !=AC !=RC !=Eq !=Un
...errors...
[10/22/2013 - 03:52:01PM] OnUpdate(): AW:+ RW:+ AC:! RC:! Eq:! Un:!
[10/22/2013 - 03:52:03PM] OnItemAdded(world): FF0008Be (base=A000D63 cell=32Ae7 3d=0 del=1) '[ObjectReference <Item 2 in container  (00000014)>]' ->AW !=RW !=AC !=RC !=Eq !=Un

If this log looks surprising, remember that our pointer re-caching mode is still enabled at this point. When OnItemRemoved() fires after DropObject(), the handler notices that the received pointer doesn't match the cached pointer (because the cached pointer has broken again -- notice that it compared equal to the broken pointer returned by DropObject()), so the received pointer is re-cached (->RW).

And there's another oddity here, too: after the AW pointer was broken by dropping the item to the world, it was re-cached when the item was picked up again before calling DropObject(). Then, when OnItemRemoved() fires, it gets a pointer that compares equal to the one just previously re-cached by OnItemAdded(). Also of note, this time the AW pointer remains valid even after the item is on the ground after DropObject() and OnItemRemoved(). Both of these are firsts for the scripted item; we've never seen the AW and RW pointers compare equal before, and dropping the item (either by player action or DropObject()) has always caused the AW pointer to break.

Finally, look at what happens when we pick the item up again; the pointer received by OnItemAdded() is now of the '[... <Item # in container (00000014)>]' variety, which has also never happened in any of the in-inventory events. It also compares unequal to the last pointer we saw in OnItemAdded(), which causes the new one to be re-cached again ("->AW").