Add logs for scheduled callback execution

emulator/blockchain.go

@@ -1935,13 +1935,13 @@ func (b *Blockchain) executeScheduledTransactions(blockContext fvm.Context) ([]*
 		return results, err
 	}
 	pendingExecutionEvents := filterPendingExecutionEvents(sdkEvents, serviceAddress)
-	executeTxs, err := executeScheduledTransactions(pendingExecutionEvents, serviceAddress, parentID)
+	executeTxs, scheduledIDs, err := executeScheduledTransactions(pendingExecutionEvents, serviceAddress, parentID)
 	if err != nil {
 		return results, err
 	}
 
 	// execute scheduled transactions out-of-band
-	for _, tx := range executeTxs {
+	for idx, tx := range executeTxs {
 		execSnapshot, execOutput, err := b.vm.Run(
 			ctx,
 			fvm.Transaction(&tx, uint32(len(b.pendingBlock.Transactions()))),
@@ -1950,6 +1950,18 @@ func (b *Blockchain) executeScheduledTransactions(blockContext fvm.Context) ([]*
 		if err != nil {
 			return results, err
 		}
+
+		// Print scheduled transaction result (labeled), including app-level scheduled tx id
+		schedResult, err := convert.VMTransactionResultToEmulator(tx.ID(), execOutput)
+		if err != nil {
+			return results, err
+		}
+		appScheduledID := ""
+		if idx < len(scheduledIDs) {
+			appScheduledID = scheduledIDs[idx]
+		}
+		utils.PrintScheduledTransactionResult(&b.conf.ServerLogger, schedResult, appScheduledID)
+
 		b.pendingBlock.events = append(b.pendingBlock.events, execOutput.Events...)
 		if err := b.pendingBlock.ledgerState.Merge(execSnapshot); err != nil {
 			return results, err

emulator/scheduled_transactions.go

@@ -86,8 +86,10 @@ func executeScheduledTransactions(
 	pendingExecutionEvents []flowsdk.Event,
 	serviceAddress flowgo.Address,
 	parentID flowgo.Identifier,
-) ([]flowgo.TransactionBody, error) {
-	var transactions []flowgo.TransactionBody
+) (transactions []flowgo.TransactionBody, scheduledIDs []string, err error) {
+	transactions = make([]flowgo.TransactionBody, 0)
+	scheduledIDs = make([]string, 0)
+
 	env := templates.Environment{
 		FlowTransactionSchedulerAddress: serviceAddress.HexWithPrefix(),
 	}
@@ -97,7 +99,7 @@ func executeScheduledTransactions(
 	for _, e := range pendingExecutionEvents {
 		id, _, limit, _, err := parseSchedulerPendingExecutionEvent(e, serviceAddress)
 		if err != nil {
-			return nil, err
+			return nil, nil, err
 		}
 
 		txBuilder := flowgo.NewTransactionBodyBuilder().
@@ -110,13 +112,14 @@ func executeScheduledTransactions(
 
 		tx, err := txBuilder.Build()
 		if err != nil {
-			return nil, err
+			return nil, nil, err
 		}
 
 		transactions = append(transactions, *tx)
+		scheduledIDs = append(scheduledIDs, string(id))
 	}
 
-	return transactions, nil
+	return transactions, scheduledIDs, nil
 }
 
 // parseSchedulerPendingExecutionEvent parses flow event that is emitted during scheduler

utils/logging.go

@@ -88,6 +88,44 @@ func PrintTransactionResult(logger *zerolog.Logger, result *types.TransactionRes
 	}
 }
 
+// PrintScheduledTransactionResult prints a clearly labeled log entry for scheduled transactions
+// execute transactions so they can be easily distinguished from user transactions.
+func PrintScheduledTransactionResult(logger *zerolog.Logger, result *types.TransactionResult, scheduledTxID string) {
+	if result.Succeeded() {
+		logger.Debug().
+			Str("systemTxId", result.TransactionID.String()).
+			Str("scheduledTxId", scheduledTxID).
+			Uint64("computationUsed", result.ComputationUsed).
+			Uint64("memoryEstimate", result.MemoryEstimate).
+			Str("kind", "scheduled").
+			Msg("⏱️  Scheduled transaction executed")
+	} else {
+		logger.Warn().
+			Str("systemTxId", result.TransactionID.String()).
+			Str("scheduledTxId", scheduledTxID).
+			Uint64("computationUsed", result.ComputationUsed).
+			Uint64("memoryEstimate", result.MemoryEstimate).
+			Str("kind", "scheduled").
+			Msg("❗  Scheduled transaction reverted")
+	}
+
+	for _, event := range result.Events {
+		logger.Debug().Msgf(
+			"%s %s",
+			logPrefix("EVT-SYS", result.TransactionID, aurora.GreenFg),
+			event,
+		)
+	}
+
+	if !result.Succeeded() {
+		logger.Warn().Msgf(
+			"%s %s",
+			logPrefix("ERR-SYS", result.TransactionID, aurora.RedFg),
+			result.Error.Error(),
+		)
+	}
+}
+
 func logPrefix(prefix string, id flowsdk.Identifier, color aurora.Color) string {
 	prefix = aurora.Colorize(prefix, color|aurora.BoldFm).String()
 	shortID := fmt.Sprintf("[%s]", id.String()[:6])