Add log messages for significant events

[anorth]

The runtime API exposes a logging hook, which we currently make scarce use of. Log messages could be extremely helpful when debugging actor behaviour in the wild, especially if something unexpected is happening.

Add informational log messages around significant events.

Note that the Runtime will know which the receiving actor is, so it's not necessary to add that information into the message body. The runtime will also know the method number, parameters etc.

Be very careful that log message formatting does not alter the actor behaviour (e.g. by dereferencing a nil that otherwise would be ignored).

[wadealexc]

Cron

• Log when an entry fails:

  specs-actors/actors/builtin/cron/cron_actor.go

  Lines 38 to 41 in bcd83e8

  	for _, entry := range st.Entries {
  	_, _ = rt.Send(entry.Receiver, entry.MethodNum, nil, abi.NewTokenAmount(0))
  	// Any error and return value are ignored.
  	}

Market

• OnMinerSectorsTerminate:
  • Log when a deal isn't found:

    specs-actors/actors/builtin/market/market_actor.go

    Lines 406 to 410 in bcd83e8

    	// deal could have terminated and hence deleted before the sector is terminated.
    	// we should simply continue instead of aborting execution here if a deal is not found.
    	if !found {
    	continue
    	}

  • Log when a deal is expired:

    specs-actors/actors/builtin/market/market_actor.go

    Lines 414 to 417 in bcd83e8

    	// do not slash expired deals
    	if deal.EndEpoch <= params.Epoch {
    	continue
    	}

  • Log if a deal has been slashed:

    specs-actors/actors/builtin/market/market_actor.go

    Lines 425 to 428 in bcd83e8

    	// if a deal is already slashed, we don't need to do anything here.
    	if state.SlashEpoch != epochUndefined {
    	continue
    	}

Power

• SubmitPoRepForBulkVerify:
  • Log when ProofValidationBatch is created (expected once per epoch):

    specs-actors/actors/builtin/power/power_actor.go

    Lines 248 to 250 in bcd83e8

    	if st.ProofValidationBatch == nil {
    	mmap = adt.MakeEmptyMultimap(store)
    	} else {

• processBatchProofVerifies:
  • Log if ProofValidationBatch is nil:

    specs-actors/actors/builtin/power/power_actor.go

    Lines 311 to 313 in bcd83e8

    	if st.ProofValidationBatch == nil {
    	return
    	}

  • Log if duplicate proof skipped:

    specs-actors/actors/builtin/power/power_actor.go

    Lines 356 to 359 in bcd83e8

    	if _, exists := seen[snum]; exists {
    	// filter-out duplicates
    	continue
    	}

  • Log if proof failed (if !r):

    specs-actors/actors/builtin/power/power_actor.go

    Line 353 in bcd83e8

    if r {

  • Log if ConfirmSectorProofsValid fails:

    specs-actors/actors/builtin/power/power_actor.go

    Lines 366 to 372 in bcd83e8

    	// The exit code is explicitly ignored
    	_, _ = rt.Send(
    	m,
    	builtin.MethodsMiner.ConfirmSectorProofsValid,
    	&builtin.ConfirmSectorProofsParams{Sectors: successful},
    	abi.NewTokenAmount(0),
    	)

• processDeferredCronEvents:
  • Log if no events are loaded (if len(epochEvents) == 0):

    specs-actors/actors/builtin/power/power_actor.go

    Lines 391 to 394 in bcd83e8

    	if len(epochEvents) > 0 {
    	err = events.RemoveAll(epochKey(epoch))
    	builtin.RequireNoErr(rt, err, exitcode.ErrIllegalState, "failed to clear cron events at %v", epoch)
    	}

VerifReg

• RestoreBytes: Log if this method is invoked

Miner

• burnFunds: Log if this method is invoked with nonzero amt
• RepayDebtsOrAbort: Log if this method is invoked and succeeds
• SubmitWindowedPoSt:
  • Log if all sectors are faults (if len(sectorsInfos) == 0):

    specs-actors/actors/builtin/miner/miner_actor.go

    Lines 392 to 394 in bcd83e8

    	// Skip verification if all sectors are faults.
    	// We still need to allow this call to succeed so the miner can declare a whole partition as skipped.
    	if len(sectorInfos) > 0 {

• OnDeferredCronEvent: Add a default case, and log if it's reached
• processEarlyTerminations:
  • Log if early terminations are empty:

    specs-actors/actors/builtin/miner/miner_actor.go

    Lines 1595 to 1600 in bcd83e8

    	// Nothing to do, don't waste any time.
    	// This can happen if we end up processing early terminations
    	// before the cron callback fires.
    	if result.IsEmpty() {
    	return
    	}

  • Log if early terminations are empty, pt 2:

    specs-actors/actors/builtin/miner/miner_actor.go

    Lines 1642 to 1645 in bcd83e8

    	// We didn't do anything, abort.
    	if result.IsEmpty() {
    	return more
    	}

• scheduleEarlyTerminationWork: Log if this method is invoked

[anorth]

We've determined this is not critical for network launch. It will greatly aid troubleshooting, but does not itself resolve or reduce any specific risk.

cc @wadealexc

[ZenGround0]

#1288 can be done as part of this work.