From 51154994bf4c64b07c9e8641cfbb64e012bc1929 Mon Sep 17 00:00:00 2001 From: William Kennedy Date: Mon, 5 Feb 2024 08:48:03 +0200 Subject: [PATCH] fixed logging --- app/services/engine/main.go | 1 - .../engine/v1/handlers/gamegrp/gamegrp.go | 6 +-- business/core/game/game.go | 54 ++++++------------- business/web/v1/mid/logger.go | 13 +++-- 4 files changed, 28 insertions(+), 46 deletions(-) diff --git a/app/services/engine/main.go b/app/services/engine/main.go index 0ff2cefe..6b196176 100644 --- a/app/services/engine/main.go +++ b/app/services/engine/main.go @@ -32,7 +32,6 @@ import ( /* -- Game Engine - Fixing logging with GameID Fix CheckDatabase function to test more fields Add flags to migrate command Finish dbGame package to handle all tables on to functions. diff --git a/app/services/engine/v1/handlers/gamegrp/gamegrp.go b/app/services/engine/v1/handlers/gamegrp/gamegrp.go index 82e95ff1..3139121a 100644 --- a/app/services/engine/v1/handlers/gamegrp/gamegrp.go +++ b/app/services/engine/v1/handlers/gamegrp/gamegrp.go @@ -232,9 +232,8 @@ func (h *handlers) newGame(ctx context.Context, w http.ResponseWriter, r *http.R subjectID := mid.GetSubject(ctx).String() - h.log.Info(ctx, "evts.addPlayerToGame", "gameID", g.ID(), "account", subjectID) if err := evts.addPlayerToGame(g.ID(), subjectID); err != nil { - h.log.Info(ctx, "evts.addPlayerToGame", "ERROR", err, "account", subjectID) + return v1.NewTrustedError(fmt.Errorf("unable to add player %q to game: %w", subjectID, err), http.StatusBadRequest) } ctx = web.SetParam(ctx, "id", g.ID().String()) @@ -269,9 +268,8 @@ func (h *handlers) join(ctx context.Context, w http.ResponseWriter, r *http.Requ return v1.NewTrustedError(err, http.StatusBadRequest) } - h.log.Info(ctx, "evts.addPlayerToGame", "gameID", g.ID(), "account", subjectID) if err := evts.addPlayerToGame(g.ID(), subjectID.String()); err != nil { - h.log.Info(ctx, "evts.addPlayerToGame", "ERROR", err, "account", subjectID) + return v1.NewTrustedError(fmt.Errorf("unable to add player %q to game: %w", subjectID, err), http.StatusBadRequest) } evts.send(ctx, g.ID(), "join") diff --git a/business/core/game/game.go b/business/core/game/game.go index 9c503978..cb569ff1 100644 --- a/business/core/game/game.go +++ b/business/core/game/game.go @@ -119,10 +119,7 @@ func (g *Game) Status() string { // function will return an error. func (g *Game) AddAccount(ctx context.Context, player common.Address) error { g.mu.Lock() - defer func() { - g.mu.Unlock() - g.log.Info(ctx, "game.addaccount", "id", g.id, "player", player, "anteUSD", g.anteUSD) - }() + defer g.mu.Unlock() var empty common.Address if player == empty { @@ -174,10 +171,7 @@ func (g *Game) AddAccount(ctx context.Context, player common.Address) error { // StartGame changes the status to Playing to allow the game to begin. func (g *Game) StartGame(ctx context.Context) error { g.mu.Lock() - defer func() { - g.mu.Unlock() - g.log.Info(ctx, "game.startgame", "id", g.id) - }() + defer g.mu.Unlock() if g.status != StatusNewGame { return fmt.Errorf("game status is required to be over: status[%s]", g.status) @@ -199,10 +193,7 @@ func (g *Game) StartGame(ctx context.Context) error { // the round if there is only 1 left. func (g *Game) ApplyOut(ctx context.Context, player common.Address, outs int) error { g.mu.Lock() - defer func() { - g.mu.Unlock() - g.log.Info(ctx, "game.applyout", "id", g.id, "player", player) - }() + defer g.mu.Unlock() var empty common.Address if player == empty { @@ -294,10 +285,7 @@ func (g *Game) rollDice(ctx context.Context, player common.Address, manualRole . // the next player is determined and set. func (g *Game) Bet(ctx context.Context, player common.Address, number int, suit int) error { g.mu.Lock() - defer func() { - g.mu.Unlock() - g.log.Info(ctx, "game.bet", "id", g.id, "player", player, "number", number, "suit", suit) - }() + defer g.mu.Unlock() var empty common.Address if player == empty { @@ -353,10 +341,7 @@ func (g *Game) Bet(ctx context.Context, player common.Address, number int, suit // NextTurn determines which account makes the next move. func (g *Game) NextTurn(ctx context.Context) error { g.mu.Lock() - defer func() { - g.mu.Unlock() - g.log.Info(ctx, "game.nextturn", "id", g.id, "playerturn", g.playerTurn) - }() + defer g.mu.Unlock() if g.status != StatusPlaying { return fmt.Errorf("game status is required to be playing: status[%s]", g.status) @@ -392,10 +377,7 @@ func (g *Game) nextTurn() { // loser of the current round. func (g *Game) CallLiar(ctx context.Context, player common.Address) (winningPlayer common.Address, losingPlayer common.Address, err error) { g.mu.Lock() - defer func() { - g.mu.Unlock() - g.log.Info(ctx, "game.callliar", "id", g.id, "player", player) - }() + defer g.mu.Unlock() var empty common.Address @@ -464,7 +446,7 @@ func (g *Game) CallLiar(ctx context.Context, player common.Address) (winningPlay // Since nothing happens to the bank, no one is losing money nor is // money held hostage. if err := g.storer.InsertRound(ctx, g.state()); err != nil { - g.log.Error(ctx, "liar.store.insertRound", "ERROR", err) + g.log.Error(ctx, "liar.store.insertRound", "id", g.id, "ERROR", err) } return g.playerLastWin, g.playerLastOut, nil @@ -475,10 +457,7 @@ func (g *Game) CallLiar(ctx context.Context, player common.Address) (winningPlay // in the game. func (g *Game) NextRound(ctx context.Context) (int, error) { g.mu.Lock() - defer func() { - g.mu.Unlock() - g.log.Info(ctx, "game.callliar", "id", g.id, "round", g.round) - }() + defer g.mu.Unlock() if g.status != StatusRoundOver { return 0, errors.New("current round is not over") @@ -534,8 +513,8 @@ func (g *Game) NextRound(ctx context.Context) (int, error) { // Reconcile calculates the game pot and make the transfer to the winner. func (g *Game) Reconcile(ctx context.Context) (*types.Transaction, *types.Receipt, error) { - g.mu.RLock() - defer g.mu.RUnlock() + g.mu.Lock() + defer g.mu.Unlock() if g.status != StatusGameOver { return nil, nil, fmt.Errorf("game status is required to be gameover: status[%s]", g.status) @@ -554,9 +533,9 @@ func (g *Game) Reconcile(ctx context.Context) (*types.Transaction, *types.Receip gameFeeGWei := g.converter.USD2GWei(big.NewFloat(g.anteUSD)) // Log the winner and losers. - g.log.Info(ctx, "game.reconcole", "winner", g.playerLastWin) + g.log.Info(ctx, "game.reconcole", "id", g.id, "winner", g.playerLastWin) for _, player := range losingPlayers { - g.log.Info(ctx, "game.reconcole", "loser", player) + g.log.Info(ctx, "game.reconcole", "id", g.id, "loser", player) } // Perform the reconcile against the bank. @@ -564,13 +543,14 @@ func (g *Game) Reconcile(ctx context.Context) (*types.Transaction, *types.Receip if err != nil { return nil, nil, fmt.Errorf("failed to reconcile the game: %w", err) } - g.log.Info(ctx, "game.reconcole.contract", "tx", g.converter.CalculateTransactionDetails(tx), "receipt", g.converter.CalculateReceiptDetails(receipt, tx.GasPrice())) + + g.log.Info(ctx, "game.reconcole.contract", "id", g.id, "tx", g.converter.CalculateTransactionDetails(tx), "receipt", g.converter.CalculateReceiptDetails(receipt, tx.GasPrice())) g.status = StatusReconciled g.round++ // Update the player balances. - g.log.Info(ctx, "game.reconcole.fees", "anteUSD", g.anteUSD, "antiGWei", antiGWei, "gameFeeGWei", gameFeeGWei) + g.log.Info(ctx, "game.reconcole.fees", "id", g.id, "anteUSD", g.anteUSD, "antiGWei", antiGWei, "gameFeeGWei", gameFeeGWei) for i, player := range g.players { balanceGwei, err := g.banker.AccountBalance(ctx, player) if err != nil { @@ -585,11 +565,11 @@ func (g *Game) Reconcile(ctx context.Context) (*types.Transaction, *types.Receip Amount: balanceGwei, } - g.log.Info(ctx, "game.reconcole.updatebalance", "player", player, "oldBlanceGWei", oldBalanceGWei, "balanceGWei", balanceGwei) + g.log.Info(ctx, "game.reconcole.updatebalance", "id", g.id, "player", player, "oldBlanceGWei", oldBalanceGWei, "balanceGWei", balanceGwei) } if err := g.storer.InsertRound(ctx, g.state()); err != nil { - g.log.Error(ctx, "reconcile.store.insertRound", "ERROR", err) + g.log.Error(ctx, "reconcile.store.insertRound", "id", g.id, "ERROR", err) } return tx, receipt, nil diff --git a/business/web/v1/mid/logger.go b/business/web/v1/mid/logger.go index 098b53db..14306e55 100644 --- a/business/web/v1/mid/logger.go +++ b/business/web/v1/mid/logger.go @@ -2,6 +2,7 @@ package mid import ( "context" + "fmt" "net/http" "time" @@ -16,13 +17,17 @@ func Logger(log *logger.Logger) web.MidHandler { h := func(ctx context.Context, w http.ResponseWriter, r *http.Request) error { v := web.GetValues(ctx) - log.Info(ctx, "request started", "method", r.Method, "path", r.URL.Path, - "remoteaddr", r.RemoteAddr) + path := r.URL.Path + if r.URL.RawQuery != "" { + path = fmt.Sprintf("%s?%s", path, r.URL.RawQuery) + } + + log.Info(ctx, "request started", "method", r.Method, "path", path, "remoteaddr", r.RemoteAddr) err := handler(ctx, w, r) - log.Info(ctx, "request completed", "method", r.Method, "path", r.URL.Path, - "remoteaddr", r.RemoteAddr, "statuscode", v.StatusCode, "since", time.Since(v.Now)) + log.Info(ctx, "request completed", "method", r.Method, "path", path, "remoteaddr", r.RemoteAddr, + "statuscode", v.StatusCode, "since", time.Since(v.Now).String()) return err }