Tests fail, timezone weirdness ensues #16

jamesharr · 2013-11-24T05:06:18Z

I stumbled onto a strange timezone bug while running tests. It could very well be my install of Go. I'm running 1.2rc5 on darwin_amd64. I'll see what I can dig up tomorrow, but I figured I'd write down my notes.

I expanded the test to add some debugging info.

func TestFindOrCreate(t *testing.T) {
        ...
        var tmp User
        db.Where(&User{Name: "find or create"}).Find(&tmp)
        t.Logf("tmp=%v", tmp)

        q := db.Where(&User{Name: "find or create"}).Assign(User{Age: 44}).FirstOrCreate(&user6)
        if user6.Name != "find or create" || user6.Id == 0 || user6.Age != 44 {
                t.Errorf("user should be found and updated with assigned attrs")
        }
        if q.Error != nil {
                t.Errorf("Error: %v", q.Error)
        }
        ...
}

Output:

-- FAIL: TestFindOrCreate (0.01 seconds)
    gorm_test.go:1071: tmp={13 -0001-12-31 18:09:24 -0409 -0409 33 find or create 2013-11-23 22:48:56.622898 -0600 -0600 2013-11-23 22:48:56.6229 -0600 -0600 -0001-12-31 18:09:24 -0409 -0409 [] {0    0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC} {0 false} {0    0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC} 0 {0  {0 false} 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC 0001-01-01 00:00:00 +0000 UTC} [] 0}
    gorm_test.go:1078: Error: pq: invalid input syntax for type timestamp with time zone: "-0001-12-31T18:09:24-04:09"
    gorm_test.go:1083: user should be found and updated with assigned attrs
FAIL

When I turn on query logging in GORM, I see this:

sql601.851usINSERT INTO users (birthday,age,deleted_at,password_hash,name,created_at,updated_at,billing_address_id,shipping_address_id) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) RETURNING "id"[0001-01-01 00:00:00 +0000 UTC 33 0001-01-01 00:00:00 +0000 UTC [] find or create 2013-11-23 22:57:58.690353832 -0600 CST 2013-11-23 22:57:58.690355235 -0600 CST {0 false} 0]
...
sql253.948usUPDATE users SET birthday = $1, age = $2, name = $3, created_at = $4, updated_at = $5, deleted_at = $6, shipping_address_id = $7, password_hash = $8, billing_address_id = $9 WHERE (deleted_at IS NULL OR deleted_at <= '0001-01-02') AND (id = $10) AND ((name = $11))[-0001-12-31 18:09:24 -0409 -0409 44 find or create 2013-11-23 22:57:58.690354 -0600 -0600 2013-11-23 22:57:58.698527043 -0600 CST -0001-12-31 18:09:24 -0409 -0409 0 [] {0 false} 13 find or create]
...
sql246.245usUPDATE users SET age = $1, updated_at = $2, deleted_at = $3, password_hash = $4, birthday = $5, name = $6, created_at = $7, billing_address_id = $8, shipping_address_id = $9 WHERE (deleted_at IS NULL OR deleted_at <= '0001-01-02') AND (id = $10) AND ((name = $11))[44 2013-11-23 22:38:37.686012577 -0600 CST -0001-12-31 18:09:24 -0409 -0409 [] -0001-12-31 18:09:24 -0409 -0409 find or create 2013-11-23 22:38:37.679395 -0600 -0600 {0 false} 0 13 find or create]

This is what I see in postgres after the test fails:

gorm=# select * from users where name='find or create';
-[ RECORD 1 ]-------+--------------------------------
id                  | 13
birthday            | 0001-12-31 18:09:24-05:50:36 BC
age                 | 33
name                | find or create
created_at          | 2013-11-23 22:45:33.268583-06
updated_at          | 2013-11-23 22:45:33.268584-06
deleted_at          | 0001-12-31 18:09:24-05:50:36 BC
billing_address_id  |
shipping_address_id | 0
password_hash       | \x

Quite a few deleted_at dates have a strange timezone like this (all but one). I'll see what I can dig up tomorrow, but I'm going to crash for tonight.

I think I might also look at checking for query errors in tests. I think this is happening on the products table as well.

The text was updated successfully, but these errors were encountered:

jinzhu · 2013-11-24T05:51:28Z

Could you post the outputs of below codes in your local?

package main

import "fmt"
import "time"

func main() {
    var t time.Time
    fmt.Println(t)
}

I guess it is your local problem.

jamesharr · 2013-11-24T11:49:17Z

0001-01-01 00:00:00 +0000 UTC

I think you might be right, though. Looks like the memory is not being zeroed. I'll try with a different distribution of Go (I was encountering this error with 1.1.x https://code.google.com/p/go/issues/detail?id=6515)

Most of the timezones actually make it through OK

gorm=# select created_at, updated_at, deleted_at from users;
          created_at           |          updated_at           |           deleted_at
-------------------------------+-------------------------------+---------------------------------
 2013-11-23 22:57:58.590727-06 | 2013-11-23 22:57:58.590729-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.595065-06 | 2013-11-23 22:57:58.595067-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.593766-06 | 2013-11-23 22:57:58.595854-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.599053-06 | 2013-11-23 22:57:58.599075-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.598174-06 | 2013-11-23 22:57:58.598175-06 | 2013-11-23 22:57:58.599812-06
 2013-11-23 22:57:58.601707-06 | 2013-11-23 22:57:58.601708-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.629403-06 | 2013-11-23 22:57:58.63039-06  | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.686826-06 | 2013-11-23 22:57:58.686827-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.690354-06 | 2013-11-23 22:57:58.690355-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.692893-06 | 2013-11-23 22:57:58.692895-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.695043-06 | 2013-11-23 22:57:58.695045-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.726714-06 | 2013-11-23 22:57:58.726716-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.782825-06 | 2013-11-23 22:57:58.782826-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.586562-06 | 2013-11-23 22:57:58.586569-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.588104-06 | 2013-11-23 22:57:58.588105-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.588966-06 | 2013-11-23 22:57:58.588968-06 | 0001-12-31 18:09:24-05:50:36 BC
 2013-11-23 22:57:58.589875-06 | 2013-11-23 22:57:58.589876-06 | 0001-12-31 18:09:24-05:50:36 BC
(17 rows)

jinzhu · 2013-11-24T12:37:31Z

Ok, Thank you. Let me know if there are any updates.

I tested gorm with go1.2rc5 (linux gcc 4.8.2) (installed with gvm https://github.com/moovweb/gvm), and all tests passed.

So I am going to close the issue first. feel free to reopen it if you still have issue.

jamesharr · 2013-11-25T05:03:36Z

Tested with Go 1.1.2 on Ubuntu linux/amd64 and have the same issue. The problem might be with lib/pq.

gorm_test logs:

[2013-11-24 22:58:52]  [1.58ms]  INSERT INTO users (birthday,age,name,updated_at,deleted_at,shipping_address_id,created_at,billing_address_id,password_hash) VALUES ('2000-10-27 12:02:40 +0000 UTC','18','
1','2013-11-24 22:58:52.848919419 -0600 CST','0001-01-01 00:00:00 +0000 UTC','0','2013-11-24 22:58:52.84891059 -0600 CST','{0 false}','[]') RETURNING "id"

[2013-11-24 22:58:52]  [1.17ms]  INSERT INTO users (created_at,billing_address_id,password_hash,birthday,age,name,updated_at,deleted_at,shipping_address_id) VALUES ('2013-11-24 22:58:52.850864691 -0600 C
ST','{0 false}','[]','2002-01-01 00:00:00 +0000 UTC','20','2','2013-11-24 22:58:52.850869987 -0600 CST','0001-01-01 00:00:00 +0000 UTC','0') RETURNING "id"

[2013-11-24 22:58:52]  [1.62ms]  INSERT INTO users (birthday,age,name,updated_at,deleted_at,shipping_address_id,created_at,billing_address_id,password_hash) VALUES ('2005-01-01 00:00:00 +0000 UTC','22','
3','2013-11-24 22:58:52.852519176 -0600 CST','0001-01-01 00:00:00 +0000 UTC','0','2013-11-24 22:58:52.852514785 -0600 CST','{0 false}','[]') RETURNING "id"

[2013-11-24 22:58:52]  [0.98ms]  INSERT INTO users (birthday,age,name,updated_at,deleted_at,shipping_address_id,created_at,billing_address_id,password_hash) VALUES ('2010-01-01 00:00:00 +0000 UTC','24','
3','2013-11-24 22:58:52.854489327 -0600 CST','0001-01-01 00:00:00 +0000 UTC','0','2013-11-24 22:58:52.854485646 -0600 CST','{0 false}','[]') RETURNING "id"

[2013-11-24 22:58:52]  [0.95ms]  INSERT INTO users (birthday,age,name,updated_at,deleted_at,shipping_address_id,created_at,billing_address_id,password_hash) VALUES ('2010-01-01 00:00:00 +0000 UTC','26','
5','2013-11-24 22:58:52.855866734 -0600 CST','0001-01-01 00:00:00 +0000 UTC','0','2013-11-24 22:58:52.855863206 -0600 CST','{0 false}','[]') RETURNING "id"

Postgres logs

2013-11-24 22:58:52 CST LOG:  execute <unnamed>: INSERT INTO users (birthday,age,name,updated_at,deleted_at,shipping_address_id,created_at,billing_address_id,password_hash) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) RETURNING "id"
2013-11-24 22:58:52 CST DETAIL:  parameters: $1 = '2000-10-27 07:02:40-05', $2 = '18', $3 = '1', $4 = '2013-11-24 22:58:52.848919-06', $5 = '0001-12-31 18:09:24-05:50:36 BC', $6 = '0', $7 = '2013-11-24 22:58:52.848911-06', $8 = NULL, $9 = '\x'
2013-11-24 22:58:52 CST LOG:  execute <unnamed>: INSERT INTO users (created_at,billing_address_id,password_hash,birthday,age,name,updated_at,deleted_at,shipping_address_id) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) RETURNING "id"
2013-11-24 22:58:52 CST DETAIL:  parameters: $1 = '2013-11-24 22:58:52.850865-06', $2 = NULL, $3 = '\x', $4 = '2001-12-31 18:00:00-06', $5 = '20', $6 = '2', $7 = '2013-11-24 22:58:52.85087-06', $8 = '0001-12-31 18:09:24-05:50:36 BC', $9 = '0'
2013-11-24 22:58:52 CST LOG:  execute <unnamed>: INSERT INTO users (birthday,age,name,updated_at,deleted_at,shipping_address_id,created_at,billing_address_id,password_hash) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) RETURNING "id"
2013-11-24 22:58:52 CST DETAIL:  parameters: $1 = '2004-12-31 18:00:00-06', $2 = '22', $3 = '3', $4 = '2013-11-24 22:58:52.852519-06', $5 = '0001-12-31 18:09:24-05:50:36 BC', $6 = '0', $7 = '2013-11-24 22:58:52.852515-06', $8 = NULL, $9 = '\x'
2013-11-24 22:58:52 CST LOG:  execute <unnamed>: INSERT INTO users (birthday,age,name,updated_at,deleted_at,shipping_address_id,created_at,billing_address_id,password_hash) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) RETURNING "id"
2013-11-24 22:58:52 CST DETAIL:  parameters: $1 = '2009-12-31 18:00:00-06', $2 = '24', $3 = '3', $4 = '2013-11-24 22:58:52.854489-06', $5 = '0001-12-31 18:09:24-05:50:36 BC', $6 = '0', $7 = '2013-11-24 22:58:52.854486-06', $8 = NULL, $9 = '\x'
2013-11-24 22:58:52 CST LOG:  execute <unnamed>: INSERT INTO users (birthday,age,name,updated_at,deleted_at,shipping_address_id,created_at,billing_address_id,password_hash) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9) RETURNING "id"
2013-11-24 22:58:52 CST DETAIL:  parameters: $1 = '2009-12-31 18:00:00-06', $2 = '26', $3 = '5', $4 = '2013-11-24 22:58:52.855867-06', $5 = '0001-12-31 18:09:24-05:50:36 BC', $6 = '0', $7 = '2013-11-24 22:58:52.855863-06', $8 = NULL, $9 = '\x'

I'm going to see if I can get closer to isolating the bug.

jinzhu · 2013-11-25T05:29:16Z

Thank you for your update, hope you could point it out soon.

jamesharr · 2013-11-25T06:07:43Z

Yup, it's in lib/pq. I can reproduce it with this.

import (
        _ "github.com/lib/pq"
        "database/sql"
        "time"
        "fmt"
)

func main() {
        db, _ := sql.Open("postgres", "user=gorm dbname=gorm sslmode=disable")
        sql := `INSERT INTO users (deleted_at) VALUES ($1) RETURNING "id"`
        res, err := db.Exec(sql,time.Time{})
        fmt.Println(res, err)
}

Postgres logs

LOG:  execute <unnamed>: INSERT INTO users (deleted_at) VALUES ($1) RETURNING "id"
DETAIL:  parameters: $1 = '0001-12-31 18:09:24-05:50:36 BC'

What version of Postgres and lib/pq do you use? It seems to always treat the timezone as "-05:50:36" for me. Even several revisions back.

jinzhu · 2013-11-25T06:28:38Z

I am using latest lib/pq 9fa22d47b017aa81fcfd425900e2c4c48a8170a7 and postgres 9.3.1.

bendemaree · 2014-10-03T00:42:42Z

I have a (nearly) identical issue using the latest gorm, pq, etc. This is Go 1.3.3 on darwin_amd64. I ran the small test file and also received 0001-01-01 00:00:00 +0000 UTC.

The query looks like this, from the gorm logger:

UPDATE "users" SET "updated_at" = '2014-10-02 19:34:37.443809139 -0500 CDT', "deleted_at" = '-0001-12-31 18:09:24 -0550 -0550', "first_name" = '', "password" = 'mypass', "token" = 'mytoken', "created_at" = '2014-10-02 19:19:39.436759 -0500 CDT', "email" = '', "username" = 'myusername'  WHERE (deleted_at IS NULL OR deleted_at <= '0001-01-02') AND ("id" = '1')

You'll notice that the deleted_at field is incorrect and shows -0500 -0500 at the end of its timestamp.

The actual error:

pq: invalid input syntax for type timestamp with time zone: "-0001-12-31T18:09:24-05:50:36"

I added some debugging statements as deep as right after this line that show that even at this point the same -0500 -0500 string is there (I just printed out field.Field.Interface()).

Any ideas? This only happens for this DeletedAt field for this model; all others are working, despite having identical patterns.

Did you have any luck @jamesharr? I'd appreciate any help you or @jinzhu can provide.

jinzhu · 2014-10-03T12:36:01Z

Hi @bendemaree

As I remembered, I have seen similar reports before... but forgot how they fixed it

Could you provide a script that could reproduce this issue after pull latests lib/pg, so I could test it myself?

bendemaree · 2014-10-04T13:14:39Z

Sure! I will have something soon that (hopefully) reproduces.

bendemaree · 2014-10-04T13:27:55Z

Hey @jinzhu, I have created a test that fails every time on my machine.

package main

import (
        "fmt"
        "github.com/jinzhu/gorm"
        _ "github.com/lib/pq"
        "time"
)

type User struct {
        Id        int64
        Name      string
        Email     string
        CreatedAt time.Time
        UpdatedAt time.Time
        DeletedAt time.Time
}

func main() {
        db, _ := gorm.Open("postgres", "user=gorm dbname=gorm sslmode=disable")

        db.DropTableIfExists(&User{})
        db.CreateTable(&User{})
        db.AutoMigrate(&User{})

        db.LogMode(true)

        user := User{
                Name:  "Test User",
                Email: "testuser@gmail.com",
        }

        db.Save(&user)

        dbuser := User{}
        db.First(&dbuser, user.Id)

        dbuser.Email = "newemail@gmail.com"

        db.Save(&dbuser)

        testuser := User{}
        db.First(&testuser, dbuser.Id)

        fmt.Println(testuser.Email)
}

This fails for me every time with

[2014-10-04 08:26:00]  pq: invalid input syntax for type timestamp with time zone: "-0001-12-31T18:09:24-05:50:36"

If you create a Postgres database named gorm and have a user named gorm you should be able to just go run this file.

Thank you very much for investigating!

jinzhu · 2014-10-05T02:20:29Z

I haven't got any problem... could you try to update gorm and pg, then test it again?

go get -u github.com/lib/pq 
go get -u github.com/jinzhu/gorm

jinzhu · 2014-10-05T02:29:39Z

Hi @bendemaree

I see, seems it is caused by your time zone. and look back @jamesharr's comment

Yup, it's in lib/pq. I can reproduce it with this.

import (
        _ "github.com/lib/pq"
        "database/sql"
        "time"
        "fmt"
)

func main() {
        db, _ := sql.Open("postgres", "user=gorm dbname=gorm sslmode=disable")
        sql := `INSERT INTO users (deleted_at) VALUES ($1) RETURNING "id"`
        res, err := db.Exec(sql,time.Time{})
        fmt.Println(res, err)
}

Seems it is lib/pg's issue, maybe you need to open an issue there?

bendemaree · 2014-10-06T15:06:34Z

Actually @jinzhu I think you have the same issue, regardless of timezone. If you look at the deleted_at field in the third line of DB logging, you'll see +0805 +0805 where I think it should be +0800 CST. I don't know why Postgres didn't complain for you.

I have verified @jamesharr's comment as well. I also see -05:50:36 BC. I will open an issue with lib/pq. Thank you!

bendemaree · 2014-10-06T15:10:19Z

Sorry. I should have looked more closely at open issues. lib/pq#251 is open already.

bendemaree · 2014-10-06T19:54:24Z

@jinzhu If you have time, would you review my comments in lib/pq#253? I think that's the issue. I will try and make a pull request soon.

…#216, and probably go-gorm#99. Also tags go-gorm#10 and go-gorm#20.

jinzhu closed this as completed Nov 24, 2013

bendemaree mentioned this issue Oct 6, 2014

Unfiy time parsing with timestamp parsing lib/pq#253

Closed

bendemaree added a commit to bendemaree/gorm that referenced this issue Oct 14, 2014

Do not insert empty timestamps. Fixes go-gorm#16, go-gorm#74, go-gorm…

28e067f

…#216, and probably go-gorm#99. Also tags go-gorm#10 and go-gorm#20.

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Tests fail, timezone weirdness ensues #16

Tests fail, timezone weirdness ensues #16

jamesharr commented Nov 24, 2013

jinzhu commented Nov 24, 2013

jamesharr commented Nov 24, 2013

jinzhu commented Nov 24, 2013

jamesharr commented Nov 25, 2013

jinzhu commented Nov 25, 2013

jamesharr commented Nov 25, 2013

jinzhu commented Nov 25, 2013

bendemaree commented Oct 3, 2014

jinzhu commented Oct 3, 2014

bendemaree commented Oct 4, 2014

bendemaree commented Oct 4, 2014

jinzhu commented Oct 5, 2014

jinzhu commented Oct 5, 2014

bendemaree commented Oct 6, 2014

bendemaree commented Oct 6, 2014

bendemaree commented Oct 6, 2014

Tests fail, timezone weirdness ensues #16

Tests fail, timezone weirdness ensues #16

Comments

jamesharr commented Nov 24, 2013

jinzhu commented Nov 24, 2013

jamesharr commented Nov 24, 2013

jinzhu commented Nov 24, 2013

jamesharr commented Nov 25, 2013

jinzhu commented Nov 25, 2013

jamesharr commented Nov 25, 2013

jinzhu commented Nov 25, 2013

bendemaree commented Oct 3, 2014

jinzhu commented Oct 3, 2014

bendemaree commented Oct 4, 2014

bendemaree commented Oct 4, 2014

jinzhu commented Oct 5, 2014

jinzhu commented Oct 5, 2014

bendemaree commented Oct 6, 2014

bendemaree commented Oct 6, 2014

bendemaree commented Oct 6, 2014