Pending rewards reset in the morning

[CallMeFoxie]

Hello

Since I've switched to solo mining several days (a week -ish?) ago my pending rewards seem to reset sometime during the night/early morning every day.

my CPID and beacon etc are ok: http://main.gridcoinstats.eu/cpid/cbc3f2f4e582dff425f355e0c2767ef9 at 41 mag right now.

I have not staked yet since going solo, have almost 8k GRC.

$ gridcoinresearchd explainmagnitude
...
  {
    "project": "total",
    "rac": 38701.885535,
    "magnitude": 41.5
  }

yet every morning I start from 0 pending rewards:

$ gridcoinresearchd getmininginfo
{
  "blocks": 2142052,
  "stakeweight": {
    "minimum": 180,
    "maximum": 462560,
    "combined": 635816,
    "valuesum": 7947.760915350001,
    "legacy": 7947.76091535
  },
  "netstakeweight": 12071730451.02193,
  "netstakingGRCvalue": 150896630.6377741,
  "staking": true,
  "mining-error": "",
  "time-to-stake_days": 19.77722222222222,
  "expectedtime": 1708752,
  "mining-version": 11,
  "mining-created": 0,
  "mining-accepted": 0,
  "mining-kernels-found": 0,
  "stake-splitting": {
    "stake-splitting-enabled": false
  },
  "side-staking": {
    "side-staking-enabled": false
  },
  "difficulty": {
    "current": 14.51159797492793,
    "target": 16.43763784202704,
    "last-search-interval": 1610443536
  },
  "errors": "",
  "pooledtx": 0,
  "testnet": false,
  "CPID": "cbc3f2f4e582dff425f355e0c2767ef9",
  "Magnitude Unit": 0.25,
  "BoincRewardPending": 1.51824652,
  "researcher_status": "Eligible for Research Rewards",
  "current_poll": "No current polls"
}
...
$ gridcoinresearchd beaconstatus
{
  "active": [
    {
      "cpid": "cbc3f2f4e582dff425f355e0c2767ef9",
      "active": true,
      "pending": false,
      "expired": false,
      "renewable": false,
...
      "private_key_available": true,
      "magnitude": 42,
      "is_mine": true
    }
  ],
  "pending": [
  ]
}

could it be related to not staking yet? Or is it just a visual glitch? I did not see anything interesting in debug.log nor scraper (which is empty?)

Thanks, Ashley

[startailcoon]

Leaving a not here since I'm interested in this topic for the explorer. This goes by last staked block by a CPID today, not looking for a possible beacon advertisement.

[jamescowens]

This is a subtle bug and unfortunately I think it is going to require a mandatory to fix... :(.

When a beacon is advertised, it is pending until it is activated by the superblock following verification.

We have

CAmount Accrual() const override
{
    const CAmount accrual = RawAccrual();

    if (accrual > MaxReward()) {
        return MaxReward();
    }

    return accrual;
}

then

CAmount RawAccrual() const override
{
    if (m_account.LastRewardHeight() >= m_superblock.m_height) {
        return AccrualDelta(m_cpid, m_account);
    }

    if (LogInstance().WillLogCategory(BCLog::LogFlags::ACCRUAL)) {
        LogPrintf("INFO %s: CPID = %s, m_account.m_accrual = %" PRId64 ", ",
                  __func__, m_cpid.ToString(), m_account.m_accrual);
    }

    return m_account.m_accrual + AccrualDelta(m_cpid, m_account);
}

At the SB the activates the beacon, m_accrual is zero.

When the accrual snapshot is stored, no record is created in that snapshot for the new active CPID because zero value accruals are suppressed. (This in and of itself is a red herring, but it confirms m_accrual was zero at the point of the SB commit.)

//!
//! \brief Tally research rewards accrued since the current superblock
//! arrived for the snapshot accrual system.
//!
//! \param superblock Incoming superblock to calculate rewards at.
//!
void TallySuperblockAccrual(const SuperblockPtr& superblock)
{
    const SnapshotCalculator calc(superblock.m_timestamp, m_current_superblock);

    for (auto& account_pair : m_researchers) {
        const Cpid cpid = account_pair.first;
        ResearchAccount& account = account_pair.second;

        if (account.LastRewardHeight() >= m_current_superblock.m_height) {
            account.m_accrual = 0;
        }

        account.m_accrual += calc.AccrualDelta(cpid, account);
    }

    // Versions 5.0.x for the mandatory block version 11 protocol hard-fork
    // contain a bug that prevented new CPIDs from accruing rewards earlier
    // than the latest superblock because the loop above does not reconcile
    // the pending accrual for CPIDs without a research account yet.
    //
    if (!g_newbie_snapshot_fix_enabled) {
        return;
    }

    // Record snapshot accrual for any CPIDs with no accounting record as
    // of the last superblock:
    //
    for (const auto& iter : superblock->m_cpids) {
        if (m_researchers.find(iter.Cpid()) == m_researchers.end()) {
            ResearchAccount& account = m_researchers[iter.Cpid()];
            account.m_accrual = calc.AccrualDelta(iter.Cpid(), account);
        }
    }
}

Now. Here is the critical error. After this SB is committed, when Accrual() is called, m_accrual is STILL zero. Accrual() begins to increment correctly, because AccrualDelta()...

//!
//! \brief Get the accrual earned since the start of an account's accrual
//! period.
//!
//! \param cpid    CPID to calculate accrual for.
//! \param account Provides historical accrual context.
//!
//! \return Accrual earned in units of 1/100000000 GRC.
//!
CAmount AccrualDelta(const Cpid& cpid, const ResearchAccount& account) const
{
    int64_t accrual_timespan;

    // If the CPID earned a reward on or after the current superblock, we
    // calculate the reward using plain research age. The CPID carries no
    // outstanding snapshot accrual.
    //
    // For CPIDs that did not stake a block after the current superblock,
    // we calculate accrual earned since the superblock arrived and apply
    // that on top of any rewards carried by their snapshot accrual. This
    // includes newbie accounts which begin to accrue rewards after their
    // CPIDs first appear in a superblock.
    //
    if (account.LastRewardHeight() >= m_superblock.m_height) {
        accrual_timespan = AccrualAge(account);
    } else {
        accrual_timespan = SuperblockAge();
    }

    // CONSENSUS: avoid floating-point arithmetic.
    //
    // Some 32-bit x86 implementations do not perfectly conform to the IEEE
    // 754 floating-point spec for extended precision. To sustain consensus
    // on these platforms, we eschew the semantic representation of accrual
    // calculation for block version 11+ and compute accrual using integer-
    // only arithmetic. The following produces an accrual value defined by:
    //
    //   accrual_days * CurrentMagnitude(cpid) * MagnitudeUnit() * COIN
    //
    // We deconstruct the magnitude unit coefficient ratio as a reminder to
    // review this value if the protocol rule changes in the future:
    //
    const uint64_t base_accrual = accrual_timespan
        * CurrentMagnitude(cpid).Scaled()
        * MAG_UNIT_NUMERATOR;

    // If the accrual calculation will overflow a 64-bit integer, we need
    // more bits. Arithmetic with the big integer type is much slower and
    // unnecessary in the majority of cases so switch only when required:
    //
    CAmount accrual = 0;

    if (base_accrual > std::numeric_limits<uint64_t>::max() / COIN) {
        arith_uint256 accrual_bn(base_accrual);
        accrual_bn *= COIN;
        accrual_bn /= 86400;
        accrual_bn /= Magnitude::SCALE_FACTOR;
        accrual_bn /= MAG_UNIT_DENOMINATOR;

        accrual = accrual_bn.GetLow64();
    } else {
        accrual = base_accrual
                * COIN
                / 86400
                / Magnitude::SCALE_FACTOR
                / MAG_UNIT_DENOMINATOR;
    }

    if (LogInstance().WillLogCategory(BCLog::LogFlags::ACCRUAL)) {
        LogPrintf("INFO %s: CPID = %s, LastRewardHeight() = %u, accrual_timespan = %" PRId64 ", "
                  "accrual = %" PRId64 ".", __func__, cpid.ToString(), account.LastRewardHeight(),
                  accrual_timespan, accrual);
    }

    return accrual;
}

provides the correct value UNTIL the next superblock. When the next SB arrives and

//!
//! \brief Tally research rewards accrued since the current superblock
//! arrived for the snapshot accrual system.
//!
//! \param superblock Incoming superblock to calculate rewards at.
//!
void TallySuperblockAccrual(const SuperblockPtr& superblock)
{
    const SnapshotCalculator calc(superblock.m_timestamp, m_current_superblock);

    for (auto& account_pair : m_researchers) {
        const Cpid cpid = account_pair.first;
        ResearchAccount& account = account_pair.second;

        if (account.LastRewardHeight() >= m_current_superblock.m_height) {
            account.m_accrual = 0;
        }

        account.m_accrual += calc.AccrualDelta(cpid, account);
    }

    // Versions 5.0.x for the mandatory block version 11 protocol hard-fork
    // contain a bug that prevented new CPIDs from accruing rewards earlier
    // than the latest superblock because the loop above does not reconcile
    // the pending accrual for CPIDs without a research account yet.
    //
    if (!g_newbie_snapshot_fix_enabled) {
        return;
    }

    // Record snapshot accrual for any CPIDs with no accounting record as
    // of the last superblock:
    //
    for (const auto& iter : superblock->m_cpids) {
        if (m_researchers.find(iter.Cpid()) == m_researchers.end()) {
            ResearchAccount& account = m_researchers[iter.Cpid()];
            account.m_accrual = calc.AccrualDelta(iter.Cpid(), account);
        }
    }
}

AccrualDelta() collapses to zero, because of this line...

    } else {
        accrual_timespan = SuperblockAge();
    }

The Superblockage() is now ZERO, because the INCOMING superblock is used as the reference for the age instead of the last superblock. So now the Accrual() returns zero again and this repeats forever.

[jamescowens]

So the last mandatory in fact only half-fixed the original issue.

[jamescowens]

I will be pondering the best fix for this over the weekend.

[jamescowens]

@cyrossignol ^

[jamescowens]

Ok. I don't think the exact scenario I described above is happening, but I HAVE confirmed that the accrual is being lost at each superblock. I have a new branch where I am augmenting the auditing code for the accrual system and the logging to get more visibility into this. Further work will be required to trace the ultimate cause. Please see https://github.com/jamescowens/Gridcoin-Research/commits/troubleshoot_accrual.

Note that the auditsnapshotaccruals returns the following:
accrual_mismatches_20210117.log

This indicates there are 43 out of 998 accruals that mismatch, all with the same pattern that GetAccrual is only returning the last period (which appears to be the boundary between the last SB and "now"). No other discrepancies have been found. This is good in the sense that this is the only problem we have to fix.

[jamescowens]

I spent pretty much the entire weekend trying to track this down. Still have not been able to pin down precisely where the failure is. I just put in more logging in.

Something is going wrong in the following call chain...

bool TryLoadSuperblock(
CBlock& block,
const CBlockIndex* const pindex,
const GRC::Claim& claim)
{
GRC::SuperblockPtr superblock = block.GetSuperblock(pindex);

// TODO: find the invalid historical superblocks so we can remove
// the fColdBoot condition that skips this check when syncing the
// initial chain:
//
if ((!fColdBoot || block.nVersion >= 11)
    && !GRC::Quorum::ValidateSuperblockClaim(claim, superblock, pindex))
{
    return block.DoS(25, error("ConnectBlock: Rejected invalid superblock."));
}

// Block versions 11+ calculate research rewards from snapshots of
// accrual taken at each superblock:
//
if (block.nVersion >= 11) {
    if (!GRC::Tally::ApplySuperblock(superblock)) {
        return false;
    }

    GRC::GetBeaconRegistry().ActivatePending(
        superblock->m_verified_beacons.m_verified,
        superblock.m_timestamp);
}

GRC::Quorum::PushSuperblock(std::move(superblock));

return true;

}

//!
//! \brief Update the account data with information from a new superblock.
//!
//! \param superblock Refers to the current active superblock.
//!
//! \return \c false if an IO error occurred while processing the superblock.
//!
bool ApplySuperblock(SuperblockPtr superblock)
{
    // The network publishes version 2+ superblocks after the mandatory
    // switch to block version 11.
    //
    if (superblock->m_version >= 2) {
        TallySuperblockAccrual(superblock);

        if (!m_snapshots.Store(superblock.m_height, m_researchers)) {
            return false;
        }
    }

    m_current_superblock = std::move(superblock);

    return true;
}

//!
//! \brief Tally research rewards accrued since the current superblock
//! arrived for the snapshot accrual system.
//!
//! \param superblock Incoming superblock to calculate rewards at.
//!
void TallySuperblockAccrual(const SuperblockPtr& superblock)
{
    const SnapshotCalculator calc(superblock.m_timestamp, m_current_superblock);

    LogPrint(BCLog::LogFlags::ACCRUAL, "INFO %s: m_researchers.size() = %u",
             __func__, m_researchers.size());

    for (auto& account_pair : m_researchers) {
        const Cpid cpid = account_pair.first;
        ResearchAccount& account = account_pair.second;

        if (account.LastRewardHeight() >= m_current_superblock.m_height) {
            account.m_accrual = 0;
        }

        account.m_accrual += calc.AccrualDelta(cpid, account);
    }

    // Versions 5.0.x for the mandatory block version 11 protocol hard-fork
    // contain a bug that prevented new CPIDs from accruing rewards earlier
    // than the latest superblock because the loop above does not reconcile
    // the pending accrual for CPIDs without a research account yet.
    //
    if (!g_newbie_snapshot_fix_enabled) {
        return;
    }

    // Record snapshot accrual for any CPIDs with no accounting record as
    // of the last superblock:
    //
    for (const auto& iter : superblock->m_cpids) {
        if (m_researchers.find(iter.Cpid()) == m_researchers.end()) {
            ResearchAccount& account = m_researchers[iter.Cpid()];
            account.m_accrual = calc.AccrualDelta(iter.Cpid(), account);

            LogPrint(BCLog::LogFlags::ACCRUAL, "INFO %s: accrual account not found"
                     "for CPID %s. Creating account with accrual %" PRId64"."
                     "m_researchers.size() now %u", __func__, iter.Cpid().ToString(),
                     account.m_accrual, m_researchers.size());
        }
    }
}

The AccrualDelta logs from the ApplySuperblock in the debug.log for this morning's SB are here:
ApplySuperblock_AccrualDelta-20210118.log

You see there are 1847.

The output from my new listresearchaccounts RPC function:
listresearchaccounts_20210118.log

The count here shows 5933. WTF? They should be identical and here is why...

The entries in the debug.log when the SB is posted arise from the LogPrint in AccrualDelta, which in turn is called in range based for loop in TallySuperblockAccrual...

    for (auto& account_pair : m_researchers) {
        const Cpid cpid = account_pair.first;
        ResearchAccount& account = account_pair.second;

        if (account.LastRewardHeight() >= m_current_superblock.m_height) {
            account.m_accrual = 0;
        }

        account.m_accrual += calc.AccrualDelta(cpid, account);
    }

Now, the new listresearchaccounts uses

for (const auto& iter : GRC::Tally::Accounts())
{
    UniValue entry(UniValue::VOBJ);

    const GRC::Cpid& cpid = iter.first;
    const GRC::ResearchAccount& account = iter.second;
    const int64_t accrual = GRC::Tally::GetAccrual(cpid, now, pindexBest);

    entry.pushKV("cpid", cpid.ToString());
    entry.pushKV("accrual_as_of_last_superblock", account.m_accrual);
    entry.pushKV("current_accrual", accrual);

    entries.push_back(entry);
}

result.pushKV("number_of_accounts", GRC::Tally::Accounts().size());
result.pushKV("details", entries);

GRC::Tally::Accounts() returns a wrapper range around g_researcher_tally.m_researchers. A size() method is also implemented. it should return the same count! As you can see it doesn't.

See
accrual_mismatches_20210118.log

For an updated accrual audit. Notice that there are 44 mismatches. Every single one of them the accrual from Accrual() matches the last period of the audit calculation. Every single one of those also does not have a research account present. The 3 others that don't have a research account present are brand new, the accrual still matches. (That will not be true as of the next SB.)

So this confirms the scope of the problem is accrual account not actually being saved.

I sample checked the snapshot file, and they don't contain the accrual records either.

bool Store(const uint64_t height, const ResearchAccountMap& accounts)
{
    LogPrint(LogFlags::TALLY,
        "Tally: storing new accrual snapshot %" PRIu64 "...", height);

    AccrualSnapshotWriter writer(SnapshotPath(height));

    if (writer.IsNull()) {
        return error("%s: failed to open %" PRIu64, __func__, height);
    }

    try {
        writer.WriteHeader(height);

        for (const auto& account_pair : accounts) {
            if (account_pair.second.m_accrual > 0) {
                writer.WriteRecord(
                    account_pair.first, // CPID
                    account_pair.second.m_accrual);
            }
        }
    } catch (const std::exception& e) {
        return error("%s: %s", __func__, e.what());
    }

    return m_registry.Register(height, writer.GetHash());
}

Records with zero accrual are not stored. This would indicate the accrual is zero for the CPID's in question. How though? In

    // Record snapshot accrual for any CPIDs with no accounting record as
    // of the last superblock:
    //
    for (const auto& iter : superblock->m_cpids) {
        if (m_researchers.find(iter.Cpid()) == m_researchers.end()) {
            ResearchAccount& account = m_researchers[iter.Cpid()];
            account.m_accrual = calc.AccrualDelta(iter.Cpid(), account);

            LogPrint(BCLog::LogFlags::ACCRUAL, "INFO %s: accrual account not found"
                     "for CPID %s. Creating account with accrual %" PRId64"."
                     "m_researchers.size() now %u", __func__, iter.Cpid().ToString(),
                     account.m_accrual, m_researchers.size());
        }
    }

In this part of TallySuperblockAccrual, new accrual accounts are created for the CPID's with no (prior) accounting records, and the AccrualDelta is applied to the account. This is in g_researcher_tally.m_researchers. Somehow this is being zeroed out when Store is being called.

Maybe the problem is
ResearchAccount& account = m_researchers[iter.Cpid()];

When an element in a map doesn't exist by the key, the [] operator is supposed to insert (construct) a new one and return a reference to that. I don't see the problem with this code, but maybe it isn't working.

[jamescowens]

@div72 Any thoughts you might have on this would be welcome!