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

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

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.