Golang, postgres transaction: pq: unexpected transaction status in a failed transaction

Question

Go: v 1.3 db: postgres using lib/pq

I have an app that updates a postgres database. The postgres database is set up using pgbouncer.

So, with an active connection I have code to run inserts and updates. Here is the insert code:

func (sitemap *SiteMapData) InsertSiteMap(dbConnection *sql.DB) (int64, error) {

tx, err := dbConnection.Begin()
if err != nil {
    l4g.Error("InsertSiteMap: could not being transaction: %v", err)
    return 0, err
}
result, err := tx.Exec("INSERT INTO sitemap (url) VALUES($1)", sitemap.Url)

if err != nil {
    if !strings.Contains(err.Error(), "duplicate key value violates unique constraint") {
        l4g.Error("sitemapdata.InsertSiteMap: error inserting new sitemap data: %v", err)
    }
    tx.Rollback()
    return 0, nil
}

resultCount, _ := result.RowsAffected()
if err := tx.Commit(); err != nil {
    l4g.Error("InsertSiteMap: could not commit transaction: %v", err)
    return resultCount, err
}
l4g.Info("InsertSiteMap: Insert with %s completed with count: %d", sitemap.Url, resultCount)
return resultCount, nil
}

When I start up the app this works just fine as does the update code:

func (sitemap *SiteMapData) PersistSiteMapData(dbConnection *sql.DB) (int64, error) {

baseQuery, execType := sitemap.buildUpdateQuery()

// as the number of parameters in the statement may vary the following logic is needed
var result sql.Result
var execErr error

tx, err := dbConnection.Begin()
if err != nil {
    l4g.Error("PersistSiteMap: could not being transaction: %v", err)
    return 0, err
}

switch {
case execType == NoExtraDates:
    result, execErr = tx.Exec(baseQuery, sitemap.ConsecutiveFailCount, sitemap.LastAttempt.Time,
        sitemap.Etag.String, sitemap.InternalChecksum.String, sitemap.Id)
case execType == LastGatheredOnly:
    result, execErr = tx.Exec(baseQuery, sitemap.ConsecutiveFailCount, sitemap.LastAttempt.Time,
        sitemap.Etag.String, sitemap.InternalChecksum.String,
        sitemap.LastGathered.Time, sitemap.Id)
case execType == ModifiedHeaderOnly:
    result, execErr = tx.Exec(baseQuery, sitemap.ConsecutiveFailCount, sitemap.LastAttempt.Time,
        sitemap.Etag.String, sitemap.InternalChecksum.String,
        sitemap.ModifiedHeader.Time, sitemap.Id)
case execType == BothDates:
    result, execErr = tx.Exec(baseQuery, sitemap.ConsecutiveFailCount, sitemap.LastAttempt.Time,
        sitemap.Etag.String, sitemap.InternalChecksum.String,
        sitemap.LastGathered.Time, sitemap.ModifiedHeader.Time, sitemap.Id)
}

if execErr != nil {
    tx.Rollback()
    return -1, fmt.Errorf("PersistSiteMapData Error %s: %v", baseQuery, execErr)
}

resultCount, _ := result.RowsAffected()
if err := tx.Commit(); err != nil {
    l4g.Error("PersistSiteMap: could not commit transaction: %v", err)
    return resultCount, err
}
l4g.Info("PersistSiteMapData Updated sitemap %s(%d) correctly", sitemap.Url, sitemap.Id)
return resultCount, nil
}

// buildUpdateQuery returns the update query dependent on the presence of valid datetime fields.
func (sitemap *SiteMapData) buildUpdateQuery() (string, int) {
// note: lastAttempt is not covered here as this is set immediatley prior to the retrieval attempt
nextParam := 5
execType := NoExtraDates
baseQuery := "UPDATE sitemap " +
    "SET " +
    "consecutive_fail_count = $1, last_attempt = $2, etag = $3, internal_checksum = $4"

if sitemap.LastGathered.Valid {
    baseQuery = fmt.Sprintf("%s, last_gathered = $%d", baseQuery, nextParam)
    nextParam++
    execType += LastGatheredOnly
}

if sitemap.ModifiedHeader.Valid {
    baseQuery = fmt.Sprintf("%s, modified_header = $%d", baseQuery, nextParam)
    nextParam++
    execType += ModifiedHeaderOnly
}
baseQuery = fmt.Sprintf("%s WHERE id = $%d", baseQuery, nextParam)

return baseQuery, execType
}

The logs show that the updates are happening correctly at first and then I check the logs again after a while and I see :

pq: unexpected transaction status in a failed transaction

Tracking through the lib/pq code it looks like this comes about when a *sql.DB.Begin() is called and a transaction is already running.

I wonder if anyone can shed any more light on this?

I'm kinda thinking that perhaps I should track that message specifically and if I get it enter a time based retry loop? Or is there a way to find the errant transaction and kill it off?

Thanks Nathan

score 1 · Answer 1 · answered Sep 16 '14 at 21:27

1

From http://golang.org/pkg/database/sql/#DB.Begin:

Begin starts a transaction. The isolation level is dependent on the driver.

So it appears lib/pq doesn't handle isolation well for transactions.

The only workaround is to use a sync.Mutex to lock transactions locally and file a bug on their issue tracker since this is a driver bug.

answered Sep 16 '14 at 21:27

OneOfOne

95,033
20
184
185

I will look into that. In the mean time there is a discussion on the library related to this https://github.com/lib/pq/issues/225 – nathj07 Sep 18 '14 at 13:19

Golang, postgres transaction: pq: unexpected transaction status in a failed transaction

1 Answers1