NullReference in RpcAsync intermittently

Game Design
1

Hi,

We are using the RpcAsync call in our .NETCore server to send some data over to Nakama and update the leaderboard entry. Sometimes it simply nullrefs inexplicably and our users complain because the leaderboard score doesn’t post. I would say this has a 5% null ref rate at the moment. I would really appreciate it if someone could fix it. It never even sends out the call, it dies before so the RPC function is irrelevant here. I dont know what could be causing the error. Here is the call stack:

System.NullReferenceException: Object reference not set to an instance of an object.
at Nakama.HttpRequestAdapter.SendAsync(String method, Uri uri, IDictionary`2 headers, Byte body, Int32 timeout)
at Nakama.ApiClient.RpcFunc2Async(String bearerToken, String id, String payload, String httpKey)
at RBM_Server.Modules.LeaderboardModule.UpdateLeaderboard(String leaderboardId, LeaderboardEntry leaderboardEntry) in /app/RBM_Server/Modules/LeaderboardModule.cs:line 344
at RBM_Server.Modules.LeaderboardModule.UpdateLeaderboard(String leaderboardId, BattleResult battleResult) in /app/RBM_Server/Modules/LeaderboardModule.cs:line 320
at RBM_Server.Controllers.BattleController.BattleComplete(BattleCompleteRequest request) in /app/RBM_Server/Controllers/BattleController.cs:line 193

and here is a snippet of code:

var payload = new Dictionary<string, string>
{
{ “leaderboard_id”, leaderboardId },
{ “owner”, lbEntry.BattleResult.AccountId },
{ “username”, lbEntry.BattleResult.Username },
{ “score”, lbEntry.BattleResult.LeaderboardScore.ToString() },
{ “metadata”, entryJson },
}.ToJson();

_logger.LogInformation($“JSON blob >> NAKAMA: \n {payload}”);

var result = await client.RpcAsync(_settings.Key, “post_leaderboard_score”, payload);

Anybody know why this is happening?

As a side note, I probably wouldn’t need to do this at all if the leaderboard API had a GetTotalEntries call or something like it to know the total entries in the leaderboard.

Thank you in advance!

2

Another note: I am realizing now that this just started happening after we updated from 2.3.1 to 2.4.0 in our server project.

3

@newatlanta19006 I’ve double checked the release notes for the latest .NET client release. There’s nothing that would account for any change that is reflected in the stacktrace above.

I would say this has a 5% null ref rate at the moment.

This leads me to believe there’s a logic error somewhere in your code which calls into the .NET client. There’s nothing in the client which would produce non-deterministic behaviour. It would either fail or not fail but never succeed only part of the time.

Is it possible you have an error somewhere in the way your servers are setup to communicate with Nakama over the server to server (s2s) RPC function?

As a side note, I probably wouldn’t need to do this at all if the leaderboard API had a GetTotalEntries call or something like it to know the total entries in the leaderboard.

This is fine for small leaderboards but we’ve built Nakama up for games which run at massive scale. We handle games in the top 100 on mobile and a count on the size of the leaderboard would be very very database intensive and expensive to perform. What sort of use case do you have where you need the exact count of the leaderboard records?

4

I’m am definitely passing valid arguments. Our metadata is somewhat large json blob. I would expect internal functions in Nakama to never null ref and be handled. Especially when valid arguments are passed. I looked again and then null references happen in 3.2.1, just less frequently for some reason. I am going to have to switch to using the leaderboard api I guess since RpcAsync seems a bit unreliable in this situation. I still feel like that function should never null ref intermittently though.

I’m surprised no one has ever asked for total leaderboard entries. It seems extremely common to give out prizes based on rank in almost all the top 100 games (top 80% get X, top 10% get y). It doesnt seem like you would need to query the total entries but rather just keep a counter in leaderboard table whenever an entry is submitted or updated. Our solution is just to have a fake entry that has an impossibly low score so we know who the “last” place rank is. Seems very useful and surprised Nakama doesnt have this.

5

I guess since RpcAsync seems a bit unreliable in this situation

@newatlanta19006 I’ve said it once already but I’ll say it again. The RPC function is NOT unreliable it is in-use with top 100 games on mobile. There’s no scenario where it would work sometimes and not work in other cases unless there’s a root cause somewhere in your server side logic or your data inputs.

Our metadata is somewhat large json blob.

What is a “somewhat large” JSON blob in bytes?

My guess is what you think is non-determinism or an “unreliable” result is caused by the large JSON blobs you send. Have you set the socket max_message_size_bytes option in the server? If so what value do you use and what size of blobs do you send as inputs?

https://heroiclabs.com/docs/install-configuration/#socket

  • socket.max_request_size_bytes Maximum amount of data in bytes allowed to be read from the client per request. Default value is 4096.

It seems extremely common to give out prizes based on rank in almost all the top 100 games (top 80% get X, top 10% get y). […snip…] just keep a counter in leaderboard table whenever an entry is submitted or updated

You’re welcome to contribute back to the game server with this feature. Please make sure it supports leaderboards with 50M entries and does not cause write amplification with hot row mutations.

6

I appreciate your prompt reply. But if you are saying there are acceptable reasons to throw a null ref in the RPCAsync function, that just seems wrong. And I have tested this result numerous times. I have run the exact same inputs through the function with null ref sometimes failing. I understand you dont know what the cause is, but just because you run on many top 100 games doesn’t mean there isn’t a bug. Im not sure what the forums are for if not to help make Nakama better.

Perhaps you could point me to the code that might be throwing a null reference exception in that function so I can what the possible null refs are.

7

@newatlanta19006 Always happy to help resolve bugs and help on the forums as I’m sure you can see by my post history but as you did with the last reply I gave; you ignored the information I asked for.

What is a “somewhat large” JSON blob in bytes?

Have you set the socket max_message_size_bytes option in the server? If so what value do you use and what size of blobs do you send as inputs?

8

It varies but is generally ~1kb. Sometimes larger. The WriteLeaderboardRecordAsync function throws if you exceed a limit but RPCAsync does not. That being said, it doesn’t seem like a binary pass/fail based on size of payload as I have run the test with same inputs and sometimes it fails. I have not set the max_message_size_bytes. I would rather reduce our payloads for bandwidth reasons so that is something I am looking into.

9

I know this graph doesn’t mean that much to you, but here are the NREs thrown from RPCAsync over a period. The gap in the front is before we upgraded to 4.0.0 (3.2.1 - as you can there are very few NREs. The period sincy 5/15 is with the upgrade. That was the only signficant change to that part of the project. We have reduced since 5/22 and have seen a reduction in NREs. Again, only change was downgrade. Capture

10

Hmmm :thinking: what version of Nakama do you use? The default size on max_message_size_bytes and max_request_size_bytes was 1024 bytes on an older version of the server.

11

3.2.1 right now. Im checking our settings to see what max_size is.

12

Not the .NET client but the Nakama server version?

13

2.7.0+d5e0b5bb, and our max_message_size is 4096 in our settings.

14

By the way, I agree with you that problem is most likely something related to our code or inputs somehow because some of our other less heavy RPCs haven’t seen this issue as far as I can. They are much less frequently hit and carry far smaller payloads. My contention is that I dont have the information to solve the problem and my expectation would be that RPCAsync would appropriately catch and throw more informative error (like WriteLeaderboardAsync throws when the payload is too large). Write now, my plan is to switch entirely to WriteLeaderboardAsync to see if that eliminates the issue (I have a followup RPC call to simply retrieve the fake bottom rank entry I spoke about earlier). I have looked at the open source code and I am not directly seeing what the null reference could be generated from.

15

@newatlanta19006 Would you be able to share the RPC function itself that is executed with the inputs? Ideally with an example input which can be used to reproduce the problem.

The .NET client logic which appears in your stacktrace is online here:

https://github.com/heroiclabs/nakama-dotnet/blob/master/src/Nakama/HttpRequestAdapter.cs#L46

Is it possible you could upgrade the Nakama server version? I can’t see which could be linked to the problem at hand but many improvements have been made since the release you’re on.

16

Yes, it will take me a moment to put this together but I can get a configuration of the inputs that resulted in the null ref.

17

Here is the code used to make the RPC call. Below that is the json that is generated for the final payload. This code has run successfully with exact same json. While this blob is big, it succeeds >90% of time with far larger payloads. So while size might be a factor it isn’t obvious how that plays into it. Also, our Nakama server never seems to receive this request so I dont think it ever attempts to send from the HttpRequestAdapter (must be nullref before then).

  public async Task<LeaderboardEntry> UpdateLeaderboard(string leaderboardId, LeaderboardEntry leaderboardEntry)
    {
        var client = new Client(_settings.Scheme, _settings.ConnectionString, _settings.Port, _settings.Key);

        var lbEntry = leaderboardEntry;
        lbEntry.BattleResult.TrimForStorage();                //This function clears some data that isn't needed in Nakama to reduce payload size
        var entryJson = JsonConvert.SerializeObject(lbEntry); //We use JSON.NET here because TinyJson doesn't like the complexity of this object

        _logger.LogInformation($"Attempt to post score for {lbEntry?.BattleResult?.Username} with score {lbEntry?.BattleResult?.LeaderboardScore}");

        var payload = new Dictionary<string, string>
        {
            { "leaderboard_id", leaderboardId },
            { "owner",  lbEntry.BattleResult.AccountId },
            { "username",  lbEntry.BattleResult.Username },
            { "score",  lbEntry.BattleResult.LeaderboardScore.ToString() },
            { "metadata",  entryJson },
        }.ToJson();

        _logger.LogInformation($"JSON blob >> NAKAMA: \n {payload}");

        var result = await client.RpcAsync(_settings.Key, "post_leaderboard_score", payload);

        _logger.LogInformation($"NAKAMA return result:\n{result.Payload}");

        var resultpayload = result.Payload.FromJson<Dictionary<string, string>>();
        var resultJson = $"{{{resultpayload["record"]}}}";
        var resultRecord = resultJson.FromJson<ApiLeaderboardRecord>();

        if(resultRecord == null)
        {
            _logger.LogError($"Failed to retrieve a leaderboard record from Nakama!");
            return null;
        }
        var retEntry = GetLeaderboardEntryFromMetaData(resultRecord.Metadata);
        return retEntry;
    }

{
“leaderboard_id”: “DailyDungeon-5-22-2020”,
“owner”: “65349893-3d64-42d9-969c-686439d24dc1”,
“username”: “reaper”,
“score”: “34”,
“metadata”: “{"BattleResult":{"TimeCompleted":1590169741.0435808,"Username":"reaper","UserNameIcon":"60e9728a21925404c96a7e1a5ca6f3a9","AccountId":"65349893-3d64-42d9-969c-686439d24dc1","BattleId":"b8177961eee5ec2408cdd41a21e9c449","Result":0,"TimeToCompletion":986.32061767578125,"FirstTime":false,"CloneTowerFloor":0,"LeaderboardScore":34,"WeaponQuestResult":{"WeaponCharacter":null},"CharacterResults":[{"SquadId":0,"IsLeader":true,"Character":{"UnitDataID":"da609c9dc791cd4459a97adbe5fbd529","CurrentTier":3,"ShardProgress":37,"CurrentLevel":40,"XPProgress":0,"Equipment":{"Body":"7158f7092b566544795955eff86874aa","Head":"b5fde8583534ff84583a7ca4742c6ae9","Legs":"b017a902c34831b489735cca12f9ee99","Weapon":"d3354ac9c42ad8f468bbd757d72a835d"},"AbilityUpgrades":{"4149b86b4b8d9864891e82ace6e6171b":1,"9f26a41b63813f84da96f7962eb3da83":1},"ExpeditionId":"7364e950-d3f4-4741-95d3-c32274461233"},"StatTracker":null,"AbilityUsages":{},"Alive":false,"FinalHealth":0,"FinalStats":{"AggroRating":100,"PhysicalDefense":23,"HitPoints":791,"ManaPerSecond":0,"ManaPoints":0,"MoveSpeed":38,"PhysicalPower":53,"BlockAmountRating":0,"BlockChanceRating":0,"CritChanceRating":210,"CritDamageRating":82,"HealPower":36,"MagicalDefense":32,"MagicalPower":380,"PierceRating":0,"ShieldPoints":4329,"AccuracyRating":100,"CastSpeed":100,"SkillSpeed":100,"CooldownSpeed":104,"ActiveAbilityCooldownSpeed":100,"HealRecieveRating":100,"DamageRecievedRating":100,"GlobalCoolDown":100,"LeechRating":0,"Scale":100}},{"SquadId":0,"IsLeader":false,"Character":{"UnitDataID":"9932046126887f44d88f0df67ae89fce","CurrentTier":4,"ShardProgress":21,"CurrentLevel":40,"XPProgress":0,"Equipment":{"Body":"442112b2ba605e545931c72398123ac7","Head":"1f610cd0ec14e5c43b7f7bda1abf4cb6","Legs":"bea483f861a95024d967de936e8b5fe5","Weapon":"f522da2e7add15246a5ab821362a6dcf"},"AbilityUpgrades":{"7956cbbe91d5bcf4198f6f90a4165844":1},"ExpeditionId":null},"StatTracker":null,"AbilityUsages":{},"Alive":false,"FinalHealth":0,"FinalStats":{"AggroRating":100,"PhysicalDefense":52,"HitPoints":1053,"ManaPerSecond":0,"ManaPoints":0,"MoveSpeed":38,"PhysicalPower":452,"BlockAmountRating":0,"BlockChanceRating":0,"CritChanceRating":180,"CritDamageRating":82,"HealPower":41,"MagicalDefense":25,"MagicalPower":42,"PierceRating":0,"ShieldPoints":4329,"AccuracyRating":100,"CastSpeed":100,"SkillSpeed":100,"CooldownSpeed":104,"ActiveAbilityCooldownSpeed":100,"HealRecieveRating":100,"DamageRecievedRating":100,"GlobalCoolDown":100,"LeechRating":0,"Scale":100}},{"SquadId":0,"IsLeader":false,"Character":{"UnitDataID":"03fcb0f46ee1cd54bac03eabd1707975","CurrentTier":3,"ShardProgress":12,"CurrentLevel":40,"XPProgress":0,"Equipment":{"Body":"922c2e25dc548fc48b914faf8807ecca","Head":"7584c0f407e9cfb4ca1208f848792ac9","Legs":"9f36bf8ea0027a9439be4175262efcb6","Weapon":"f862102c17f6a584da8b82120783b9da"},"AbilityUpgrades":{"5e16442ade6acbc4bbc182a81a21a06d":1,"043c8f7834e063c4787a36941cc4254c":1,"80073edfac0cfaa47a186e285191e5a5":1,"93f23982b6999a44d8e83d8562696418":1},"ExpeditionId":null},"StatTracker":null,"AbilityUsages":{},"Alive":false,"FinalHealth":0,"FinalStats":{"AggroRating":50,"PhysicalDefense":40,"HitPoints":791,"ManaPerSecond":0,"ManaPoints":0,"MoveSpeed":38,"PhysicalPower":122,"BlockAmountRating":0,"BlockChanceRating":0,"CritChanceRating":120,"CritDamageRating":61,"HealPower":269,"MagicalDefense":23,"MagicalPower":45,"PierceRating":0,"ShieldPoints":4329,"AccuracyRating":100,"CastSpeed":100,"SkillSpeed":100,"CooldownSpeed":104,"ActiveAbilityCooldownSpeed":100,"HealRecieveRating":100,"DamageRecievedRating":100,"GlobalCoolDown":100,"LeechRating":0,"Scale":100}},{"SquadId":0,"IsLeader":false,"Character":{"UnitDataID":"abce88bbc55a49d43877bcad3be84213","CurrentTier":3,"ShardProgress":7,"CurrentLevel":40,"XPProgress":0,"Equipment":{"Body":"c42d91faa334220449fceff4dc3793c0","Head":"c2306a097abfc3d48b3197fe5e29b335","Legs":"46b3830a92caae641b4e3953f508956e","Weapon":"aff56401444ff584293ff30bf96e616f"},"AbilityUpgrades":{},"ExpeditionId":null},"StatTracker":null,"AbilityUsages":{},"Alive":false,"FinalHealth":0,"FinalStats":{"AggroRating":100,"PhysicalDefense":56,"HitPoints":911,"ManaPerSecond":0,"ManaPoints":0,"MoveSpeed":38,"PhysicalPower":519,"BlockAmountRating":0,"BlockChanceRating":0,"CritChanceRating":90,"CritDamageRating":61,"HealPower":7,"MagicalDefense":47,"MagicalPower":8,"PierceRating":0,"ShieldPoints":4329,"AccuracyRating":100,"CastSpeed":100,"SkillSpeed":100,"CooldownSpeed":104,"ActiveAbilityCooldownSpeed":100,"HealRecieveRating":100,"DamageRecievedRating":100,"GlobalCoolDown":100,"LeechRating":0,"Scale":100}},{"SquadId":0,"IsLeader":false,"Character":{"UnitDataID":"25e9464fb2ba19b479e71c61df57d944","CurrentTier":3,"ShardProgress":77,"CurrentLevel":40,"XPProgress":0,"Equipment":{"Body":"8fbcff096c041dd4ba534c6b2fbdff73","Head":"31385844efbba4e4798ed4b99f9cd9a8","Legs":"630f98f87ec58b442acc6c137b9c8e1d","Weapon":"89a379517201a2144a9d4ae409f79bed"},"AbilityUpgrades":{"b0e07009b7d0f9340973393beb5f05da":1,"ca4849a7e9275214e9a64d0db4ec4dab":1,"403d7b23367570b4f94a27b3aec39e28":1,"295847306c04b32448612643cc109662":1},"ExpeditionId":"d45ac45a-abca-43d7-a40c-96d68f3e40d6"},"StatTracker":null,"AbilityUsages":{},"Alive":false,"FinalHealth":0,"FinalStats":{"AggroRating":1500,"PhysicalDefense":80,"HitPoints":1662,"ManaPerSecond":0,"ManaPoints":0,"MoveSpeed":38,"PhysicalPower":77,"BlockAmountRating":0,"BlockChanceRating":0,"CritChanceRating":50,"CritDamageRating":41,"HealPower":30,"MagicalDefense":139,"MagicalPower":250,"PierceRating":0,"ShieldPoints":4329,"AccuracyRating":100,"CastSpeed":100,"SkillSpeed":100,"CooldownSpeed":104,"ActiveAbilityCooldownSpeed":100,"HealRecieveRating":100,"DamageRecievedRating":100,"GlobalCoolDown":100,"LeechRating":0,"Scale":100}}],"EnemyCharacterResults":,"EnemiesDefeated":{},"Rewards":},"TotalEntries":0,"Score":34,"Rank":0,"RewardClaimed":false}”
}

18

@newatlanta19006 To reproduce I’ll need the RPC function itself otherwise I don’t have both sides to recreate the behaviour.

19

local function post_leaderboard_score(context, payload)

local from_args = context[“query_params”][“payload”][1]

– we’ll assume payload was sent as JSON and decode it.
local json = nk.json_decode(from_args)

– log data sent to RPC call.
nk.logger_info((“post_leaderboard_score: %q”):format(from_args))

local leaderboard_id = json.leaderboard_id
local owner = json.owner
local username = json.username
local score = json.score
local metadata = {
leaderboard_entry = json.metadata
}

nk.logger_info((“post_leaderboard_score: Leadboard Id: %q Owner: %q”):format(leaderboard_id, owner))

local record = nk.leaderboard_record_write(leaderboard_id, owner, “”, tonumber(score), 0, metadata)

return nk.json_encode({[“record”] = record })
end

20

I have re-examined the data and the Nakama .NET version doesn’t actually seem to matter much as far as null-ref frequency. It seems to happen about the same on both versions. But the problem still persists. I will be rolling out a change soon that switches from RPCAsync to WriteLeaderboardRecordAsync and I am hoping that will either reveal an issue with our “metadata” that we are sending and/or fix the null references. Let me know if there is any other info I can provide.