pet eggs not given when quest ends

[Alys]

@bgmary (512cab82-38b9-46cf-b00e-8fa4efbcb575; "🔮 Beautiful Gorgeous Mary 🔮") reports: "My party just finished a pet quest-- while the eggs are unlocked in the market for me and I got the notice saying I'd defeated the boss and received the eggs, I didn't actually get any eggs. I'm certain that I actually participated in this quest as I was the one who dealt the death blow. It was the cobra quest."

I've confirmed that they were in the snake quest, the quest did end, they have an achievement for it, but according to their items data, they have not been given any snake eggs. Below is the data showing all that. (In addition, they have no Snake pet or mount.)

There's nothing relevant in Loggly for their User ID or for the party's Group ID.

In theory, it should be impossible for them to get the achievement without being given the eggs at the same time.

If they'd accidentally sold the eggs, there would be "Snake": 0 in their items.eggs object -- unless there's new code on the website or app or in a third-party library that now deletes an items entry when its number drops to zero? If there is code that does that, making it stop would be highly advantageous for troubleshooting user support problems.

Normally I'd give them the eggs straight away but this situation is unusual enough that I'd like another admin to double-check their data to ensure I haven't missed anything. I'll be explaining this to them and promising to give them the eggs as soon as another admin has looked at it.

[Alys]

Here's the data I referred to but forgot to include.

{
    "_id": "ccc7c333-2dc8-429f-afe6-03039b008d62",
    "flagCount": 0,
    "flags": {},
    "id": "ccc7c333-2dc8-429f-afe6-03039b008d62",
    "text": "`You defeated Serpent of Distraction! Questing party members receive the rewards of victory.`",
    "info": {
        "type": "boss_defeated",
        "quest": "snake"
    },
    "timestamp": "2019-09-23T07:12:25.809Z",
    "likes": {},
    "client": null,
    "uuid": "system",
    "groupId": "2029a412-ab7f-423f-bc04-8ba493dcb72e",
    "__v": 0
},
{
    "_id": "535469ed-b7e3-4ce6-80d5-a79661d6f924",
    "flagCount": 0,
    "flags": {},
    "id": "535469ed-b7e3-4ce6-80d5-a79661d6f924",
    "text": "`🔮 Beautiful Gorgeous Mary 🔮 attacks Serpent of Distraction for 551.5 damage. Serpent of Distraction attacks party for 14.6 damage.`",
    "info": {
        "type": "boss_damage",
        "user": "🔮 Beautiful Gorgeous Mary 🔮",
        "quest": "snake",
        "userDamage": "551.5",
        "bossDamage": "14.6"
    },
    "timestamp": "2019-09-23T07:12:25.771Z",
    "likes": {},
    "client": null,
    "uuid": "system",
    "groupId": "2029a412-ab7f-423f-bc04-8ba493dcb72e",
    "__v": 0
},
...
{
    "_id": "51b7cc86-8b45-4a83-a821-1acc26821e27",
    "flagCount": 0,
    "flags": {},
    "id": "51b7cc86-8b45-4a83-a821-1acc26821e27",
    "text": "`Your quest, The Serpent of Distraction, has started.`",
    "info": {
        "type": "quest_start",
        "quest": "snake"
    },
    "timestamp": "2019-09-21T21:38:28.276Z",
    "likes": {},
    "client": null,
    "uuid": "system",
    "groupId": "2029a412-ab7f-423f-bc04-8ba493dcb72e",
    "_meta": {
        "participatingMembers": "1a70a40f-b50e-4974-8386-cbcf97ac378f, 3ef19e98-db18-4099-8408-eff88382ba94, 512cab82-38b9-46cf-b00e-8fa4efbcb575, 5296d1db-9037-4fd0-abe4-fba3cc202f1a, 92834524-0943-41ab-8b28-dc54a0aa6331, d597d75e-5d81-4c11-a8f2-c07e7364a953, d7508e88-730c-4a69-87ef-312e7c5b0fdb"
    },
    "__v": 0
},

{
    "_id": "512cab82-38b9-46cf-b00e-8fa4efbcb575",
    "achievements": {
        "quests": {
            ...
            "snake": 1
        },
    },
    "items": {
        "eggs": {
            "Wolf": 0,
            "PandaCub": 0,
            "TigerCub": 0,
            "FlyingPig": 0,
            "LionCub": 0,
            "Ferret": 0,
            "Dragon": 0,
            "Cactus": 0,
            "Peacock": 0,
            "BearCub": 0,
            "Fox": 0,
            "Velociraptor": 0,
            "Frog": 0,
            "Rooster": 0,
            "Butterfly": 0,
            "Yarn": 0,
            "Unicorn": 0,
            "Penguin": 0,
            "SeaSerpent": 0,
            "Gryphon": 0,
            "Egg": 0,
            "Slime": 0,
            "Beetle": 0,
            "Rock": 0,
            "Cuttlefish": 0,
            "Octopus": 0,
            "Dolphin": 0,
            "Axolotl": 0,
            "Bunny": 0,
            "Alligator": 0
        },
    },
}

[Alys]

At least one of the other quest participants does have the eggs:

{
    "_id": "92834524-0943-41ab-8b28-dc54a0aa6331",
   "achievements.quests.snake": 1
    "items": {
        "eggs": {
            "Wolf": 3,
            "FlyingPig": 6,
            "TigerCub": 4,
            "Fox": 2,
            "LionCub": 2,
            "BearCub": 1,
            "PandaCub": 6,
            "Dragon": 4,
            "Cactus": 3,
            "Dolphin": 0,
            "Axolotl": 0,
            "SeaSerpent": 0,
            "Bunny": 0,
            "Peacock": 0,
            "Alligator": 0,
            "Snake": 3
        }
    }
}

[Alys]

I've done tests and this is irrelevant: "... unless there's new code on the website or app or in a third-party library that now deletes an items entry when its number drops to zero? If there is code that does that, making it stop would be highly advantageous for troubleshooting user support problems." (and it wouldn't be in the mobile app anyway since the app just uses the API, sorry). Selling my last Snake egg correctly results in "Snake": 0 in my data.

[Zarrindast]

Hey, I'm bgmary, the user experiencing the issue. My internet has been spotty in my current location; could flickering wifi interrupt the item update process midway and thus yield an incomplete version of what should be a single action?

I polled my party (most of whose active members read the party chat daily) and no one else came forward to report having not received the eggs, with two users (@TheJoodle and @maikacairien) now reporting having gotten the eggs.

I am ~70% confident that I did not accidentally sell the eggs.

[Alys]

@Zarrindast Hi! Thanks for taking the time to post here and for polling your party! It's useful to know that there's no other reports there for this bug.

Internet access problems shouldn't have caused this because the quest rewards are given in Habitica's database stored on its server. The website and mobile apps merely show you a view of what's stored in the database, so interruptions at your end shouldn't have any effect for this kind of bug.

I'm certain you didn't sell the eggs. I've confirmed that if you had been given eggs and sold them, your account in the database would have shown "0" for the number of Snake eggs, but what your account actually showed was no entry at all for Snake eggs, which means you were never given them.

[Alys]

To the staff:

I've looked through the code for the end of a quest and it still assigns the achievement and eggs in a single update command, although the achievement is in an $inc and the eggs are in a $set (code below). Does the database apply the inc and set separately? If the inc succeeded but the set failed, would the User.update query return success so that the retry didn't happen?

https://github.com/HabitRPG/habitica/blob/749138df4d3c3e77be1412b5033cacb4b0c51332/website/server/models/group.js#L812-L855

https://github.com/HabitRPG/habitica/blob/749138df4d3c3e77be1412b5033cacb4b0c51332/website/server/models/group.js#L797-L808

[paglias]

regarding the db update, no, single queries are atomic so if one part completed correctly the other one should have too

[Alys]

Thanks paglias! Good to know.

I've added the "priority: important" label since this bug seems inexplicable and we don't know what its impact will be, and also it results in players not getting items that they've effectively paid gems via buying a quest scroll.

If there was another items update being performed at the same time (e.g., if a user's account was in the process of being given a drop from a task at the same time that the quest ended), is it possible, that the other update would completely overwrite the quest update? I.e., the quest rewards $inc and $set are both done but then the user's entire items object is updated by the task completion drop, so that the items update from the quest completion is lost?

[paglias]

If there was another items update being performed at the same time (e.g., if a user's account was in the process of being given a drop from a task at the same time that the quest ended), is it possible, that the other update would completely overwrite the quest update?

Hmm... changes are applied separately so what could happen is that a second update changes the value to something else so it would have to be a $set that replaced the affected field but given that it completely disappeared the only options would be an $unset or a $set against a parent object.

So for example if the user had

{
...
items: {
    ....
    eggs: {..., snake: 1, ...}
    .... 
}
}

it could be affected by something replacing user.items or user.items.eggs

[Alys]

Yes, that's the sort of thing I was thinking of. Would this do it? https://github.com/HabitRPG/habitica/blob/749138df4d3c3e77be1412b5033cacb4b0c51332/website/common/script/fns/randomDrop.js#L90

If Amplitude was working, we could check to see if an egg drop had happened around the time of the quest end. :-/

[paglias]

 if (user.markModified) user.markModified('items.eggs'); 

doesn't directly change the eggs object but I can see this bug happening if the random drop happened at the same time the quest ended and the rewards were given

[Alys]

Thanks, that's what I was thinking.

Data from Amplitude shows that there were drops close to the time of the quest ending, but not within a few seconds of it:

acquireMethod Drop itemName Honey Client Event Time Sep 23, 7:12:08 am UTC

acquireMethod Drop itemName Lion Cub Egg Client Event Time Sep 23, 7:12:10 am UTC

acquireMethod Drop itemName Fish Client Event Time Sep 23, 7:12:11 am UTC

"text": "You defeated Serpent of Distraction! Questing party members receive the rewards of victory.", "timestamp": "2019-09-23T07:12:25.809Z",

acquireMethod Drop itemName Skeleton Hatching Potion Client Event Time Sep 23, 7:12:43 am UTC

[whmountains]

So, what needs to be done to fix this? Or are we still not sure?

[fmaximus]

2 ideas come to mind:

• report uncaught errors in Amplitude, to allow to investigate future similar issues.
• have a generic retry logic for mongodb optimistic locking failures

[paglias]

report uncaught errors in Amplitude, to allow to investigate future similar issues.

uncaught errors are already reported, not in Amplitude but in loggly, I haven't seen anything related to this error recently but I can look if we get a new report

[paglias]

With PR #12335 the Habitica codebase has been updated to support MongoDB 4.2 and transactions making it possible to fix this issue.

Transactions allow operations on multiple documents to be executed ensuring that either all of them are executed correctly or none, making it possible to fix this issue.

An example on using transactions can be found at https://mongoosejs.com/docs/transactions.html while more info at https://docs.mongodb.com/manual/core/transactions/. If you want to work on this issue and have any question please leave a comment!

---

This issue may benefit from transactions but I haven't investigated it enough to be sure

[Alys]

From everything I saw at the time I was looking into this, I think the most likely cause was the one described in this comment and the comments after it: https://github.com/HabitRPG/habitica/issues/11376#issuecomment-534746769 i.e., a random drop at much the same time as the quest ended could have overwritten the items object, removing the eggs that the user HAD been given when the quest ended.

So if that's true, then I believe putting the entire quest-end process inside a transaction wouldn't help, right?

[paglias]

i.e., a random drop at much the same time as the quest ended could have overwritten the items object, removing the eggs that the user HAD been given when the quest ended.

That's possible, transactions could help if we wrap everything in a transaction from the moment the user is loaded until it's finally saved. I'm a bit wary of wrapping everything into transactions though due to the performance impact it would have