Advertisement
rmloveland

GORM appears to be swallowing PG error codes

Jul 18th, 2019
245
0
Never
Not a member of Pastebin yet? Sign Up, it unlocks many cool features!
Go 6.91 KB | None | 0 0
  1. package main
  2.  
  3. // GORM appears to be swallowing the pq error codes returned by crdb_internal.force_retry() altogether.  The output at the end of this paste shows the error message from pq, but it's not exposed via GORM's db.Error, so the code below can't see it, and the retry loop thinks everything is ok when it definitely is not.
  4.  
  5. import (
  6.     "fmt"
  7.     "log"
  8.     "math"
  9.     "math/rand"
  10.     "time"
  11.  
  12.     // Import GORM-related packages.
  13.     "github.com/jinzhu/gorm"
  14.     _ "github.com/jinzhu/gorm/dialects/postgres"
  15. )
  16.  
  17. // Account is our model, which corresponds to the "accounts" database table.
  18. type Account struct {
  19.     ID      int `gorm:"primary_key"`
  20.     Balance int
  21. }
  22.  
  23. func main() {
  24.     // Connect to the "bank" database as the "maxroach" user.
  25.     const addr = "postgresql://root@localhost:26257/bank?sslmode=disable"
  26.     db, err := gorm.Open("postgres", addr)
  27.     if err != nil {
  28.         log.Fatal(err)
  29.     }
  30.     defer db.Close()
  31.  
  32.     db.LogMode(true)
  33.  
  34.     // Automatically create the "accounts" table based on the Account
  35.     // model.
  36.     db.AutoMigrate(&Account{})
  37.  
  38.     // Insert two rows into the "accounts" table.
  39.     db.Create(&Account{ID: 1, Balance: 1000})
  40.     db.Create(&Account{ID: 2, Balance: 250})
  41.  
  42.     printBalances(db)
  43.  
  44.     // Transfer funds between accounts.  To handle any possible
  45.     // transaction retry errors, we add a retry loop with exponential
  46.     // backoff to the transfer logic (see below).
  47.  
  48.     var maxRetries = 3
  49.     var amount = 100
  50.  
  51.     var fromAccount Account
  52.     var toAccount Account
  53.  
  54.     db.First(&fromAccount, 1)
  55.     db.First(&toAccount, 2)
  56.  
  57. retryLoop:
  58.     for retries := 0; retries <= maxRetries; retries++ {
  59.  
  60.         if retries == maxRetries {
  61.             fmt.Errorf("hit max of %d retries, aborting", retries)
  62.             break retryLoop
  63.         }
  64.  
  65.         err := transferFunds(db, fromAccount, toAccount, amount)
  66.  
  67.         fmt.Printf("transferFunds result struct: %+v\n", err)
  68.  
  69.         if err != nil {
  70.             // If there's an error, we try again after sleeping an
  71.             // increased amount of time, a.k.a. exponential backoff.
  72.             r := rand.New(rand.NewSource(time.Now().UnixNano()))
  73.             var sleepMs = ((int(math.Pow(2, float64(retries))) * 100) + r.Intn(100-1) + 1)
  74.             time.Sleep(time.Millisecond * time.Duration(sleepMs))
  75.         } else {
  76.             fmt.Println("no errors, breaking from 'retryLoop'!")
  77.             break retryLoop
  78.         }
  79.     }
  80.  
  81.     // Print balances after transfer to ensure that it worked.
  82.     printBalances(db)
  83.  
  84.     // Delete accounts so we can start fresh when we want to run this
  85.     // program again.
  86.     deleteAccounts(db)
  87. }
  88.  
  89. func transferFunds(db *gorm.DB, fromAccount Account, toAccount Account, amount int) error {
  90.     if fromAccount.Balance < amount {
  91.         err := fmt.Errorf("account %d balance %d is lower than transfer amount %d", fromAccount.ID, fromAccount.Balance, amount)
  92.         return err
  93.     }
  94.  
  95.     // We would like to check for the 40001 error code below, but it
  96.     // isn't clear how to get at it from GORM.  According to
  97.     // https://github.com/jinzhu/gorm/issues/17, GORM does not expose
  98.     // the PG error codes.  Therefore, we retry on any error.
  99.  
  100.     //  if err := db.Exec(
  101.     //      `UPSERT INTO accounts (id, balance) VALUES
  102.     // (?, ((SELECT balance FROM accounts WHERE id = ?) - ?)),
  103.     // (?, ((SELECT balance FROM accounts WHERE id = ?) + ?))`,
  104.     //      fromAccount.ID, fromAccount.ID, amount,
  105.     //      toAccount.ID, toAccount.ID, amount).Error; err != nil {
  106.     //      db.Exec("ROLLBACK")
  107.     //      return db.Error
  108.     //  }
  109.  
  110.     db.Exec("BEGIN")
  111.     db.Exec("SELECT now()") // Prevent automatic server-side retries.
  112.     if err := db.Exec("SELECT crdb_internal.force_retry('1s':::INTERVAL)").Error; err != nil {
  113.         fmt.Printf("db.Error: %+v\n", db.Error)
  114.         db.Exec("ROLLBACK")
  115.     } else {
  116.         db.Exec("COMMIT")
  117.     }
  118.     return nil
  119. }
  120.  
  121. func printBalances(db *gorm.DB) {
  122.     var accounts []Account
  123.     db.Find(&accounts)
  124.     fmt.Printf("Balance at '%s':\n", time.Now())
  125.     for _, account := range accounts {
  126.         fmt.Printf("%d %d\n", account.ID, account.Balance)
  127.     }
  128. }
  129.  
  130. func deleteAccounts(db *gorm.DB) error {
  131.     // Used to tear down the accounts table so we can re-run this
  132.     // program.
  133.     err := db.Exec("DELETE from accounts where ID > 0").Error
  134.     if err != nil {
  135.         return err
  136.     } else {
  137.         return nil
  138.     }
  139. }
  140.  
  141. // make
  142. // go run gorm-sample.go
  143.  
  144. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:37)
  145. // [2019-07-18 09:58:35] [1.18ms] INSERT INTO "accounts" ("id","balance") VALUES ('1','1000') RETURNING "accounts"."id"  
  146. // [1 rows affected or returned ]
  147.  
  148. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:38)
  149. // [2019-07-18 09:58:35] [0.86ms] INSERT INTO "accounts" ("id","balance") VALUES ('2','250') RETURNING "accounts"."id"  
  150. // [1 rows affected or returned ]
  151.  
  152. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:121)
  153. // [2019-07-18 09:58:35] [1.97ms] SELECT * FROM "accounts"    
  154. // [2 rows affected or returned ]
  155. // Balance at '2019-07-18 09:58:35.138652 -0400 EDT m=+0.025357396':
  156. // 1 1000
  157. // 2 250
  158.  
  159. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:52)
  160. // [2019-07-18 09:58:35] [0.77ms] SELECT * FROM "accounts"  WHERE ("accounts"."id" = 1) ORDER BY "accounts"."id" ASC LIMIT 1  
  161. // [1 rows affected or returned ]
  162.  
  163. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:53)
  164. // [2019-07-18 09:58:35] [0.58ms] SELECT * FROM "accounts"  WHERE ("accounts"."id" = 2) ORDER BY "accounts"."id" ASC LIMIT 1  
  165. // [1 rows affected or returned ]
  166.  
  167. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:108)
  168. // [2019-07-18 09:58:35] [0.13ms] BEGIN  
  169. // [0 rows affected or returned ]
  170.  
  171. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:109)
  172. // [2019-07-18 09:58:35] [0.22ms] SELECT now()  
  173. // [1 rows affected or returned ]
  174.  
  175. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:110)
  176. // [2019-07-18 09:58:35] pq: restart transaction: crdb_internal.force_retry(): TransactionRetryWithProtoRefreshError: forced by crdb_internal.force_retry() 
  177.  
  178. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:110)
  179. // [2019-07-18 09:58:35] [52.03ms] SELECT crdb_internal.force_retry('1s':::INTERVAL)  
  180. // [0 rows affected or returned ]
  181. // db.Error: <nil>
  182.  
  183. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:112)
  184. // [2019-07-18 09:58:35] [0.28ms] ROLLBACK  
  185. // [0 rows affected or returned ]
  186. // transferFunds result struct: <nil>
  187. // no errors, breaking from 'retryLoop'!
  188.  
  189. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:121)
  190. // [2019-07-18 09:58:35] [0.70ms] SELECT * FROM "accounts"    
  191. // [2 rows affected or returned ]
  192. // Balance at '2019-07-18 09:58:35.193928 -0400 EDT m=+0.080633354':
  193. // 1 1000
  194. // 2 250
  195.  
  196. // (/Users/rloveland/work/code/deemphasize-savepoints/golang/gorm-sample.go:131)
  197. // [2019-07-18 09:58:35] [1.90ms] DELETE from accounts where ID > 0  
  198. // [2 rows affected or returned ]
  199.  
  200. // Compilation finished at Thu Jul 18 09:58:35
Advertisement
Add Comment
Please, Sign In to add comment
Advertisement