metal-toolbox/hollow-serverservice

An Update and select on an existing row returns zero rows intermittently.

joelrebel opened this issue · 3 comments

joelrebel commented

A update and a subsequent select on an existing row returns zero rows.

This issue at the time of writing seems to be in crdb, and some work needs to be done
for this to be tested outside of the serverservice context using the same sqlboiler adapter.

I'm creating this ticket to track/compare notes. Its quite possible this could just be a non-issue
and turns out to be a crdb configuration/v21.1 issue, until its figured out, we'll add findings here.

The issue shows up always in the first iteration - test-0,
and shows up in atleast 3 out of 5 attempts of the test execution.

The cause is that crdb intermittently returns no rows for the select
statement.

OS: macos
crdb server: v21.1

In the failed senario, the count(*) returns 1 row as expected, but the final select returns no rows, no NumRows in exec log.

I220713 07:17:45.721420 12485075 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:55636›,hostnossl,user=root] 1975 ={"Timestamp":1657696665718409000,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-0'›","‹'Left'›","‹'f940627a-8474-41c0-ab37-f4a810c97916'›","‹'84735c80-a711-4597-950e-1021b6376bc0'›","‹'2022-07-13 07:17:45.688831+00:00'›","‹'666a55ed-74ed-484a-aa62-705ec2524236'›"],"ExecMode":"exec","NumRows":1,"Age":3.1635,"TxnCounter":2}

I220713 07:17:46.752804 12485023 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:55634›,hostnossl,user=root] 1978 ={"Timestamp":1657696666748893500,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-0'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":4.1912,"FullTableScan":true,"TxnCounter":50}

I220713 07:17:46.759494 12485023 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:55634›,hostnossl,user=root] 1979 ={"Timestamp":1657696666756782500,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-0'›","‹'Right'›"],"ExecMode":"exec","Age":2.8987,"FullTableScan":true,"TxnCounter":51}

In the successful senario, the count(*) and the select returns 1 row "NumRows":1

I220713 07:21:55.693586 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3535 ={"Timestamp":1657696915690572800,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-0'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:55.683093+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":3.1143,"TxnCounter":2}

I220713 07:21:55.715837 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3538 ={"Timestamp":1657696915713834500,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-0'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.1364,"FullTableScan":true,"TxnCounter":50}

I220713 07:21:55.721582 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3539 ={"Timestamp":1657696915719081000,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-0'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.6206,"FullTableScan":true,"TxnCounter":51}

fixes attempted

  • Run tests serially with -p1.
  • Run Update without the transaction block.
  • Add delay between Update and List(Select)

To reproduce this issue,

setup the test db

make docker-up
make test-database

export env variable to execute test manually

export SERVERSERVICE_DB_URI="host=localhost port=26257 user=root
sslmode=disable dbname=serverservice_test

save reproducer as a test file

The test loop here updates a component model attribute
the loop is set to a high value to prevent the test from being cached,
assuming the user does not run the test for the 2000 iterations.

func TestLoopUpdate(t *testing.T) {
        s := serverTest(t)

    // this is here just to get a test auth token
        realClientTests(t, func(ctx context.Context, authToken string, respCode int, expectError bool) error {
                s.Client.SetToken(authToken)
                attrs, _, err := s.Client.GetComponents(ctx, uuid.MustParse(dbtools.FixtureNemo.ID), nil)
                if !expectError {
                        require.NoError(t, err)
                        assert.Len(t, attrs, 2)
                }

                return err
        })

    // list current servers
        servers, _, err := s.Client.List(context.Background(), nil)
        if err != nil {
                t.Fatal(err)
        }

    // the components for update
        componentSliceFixture := func() []serverservice.ServerComponent {
                s := serverservice.ServerComponentSlice{}

                for _, c := range servers[0].Components {
                        c := c
                        s = append(s, c)
                }

                return s
        }

    // component list query params
        params := &serverservice.ServerComponentListParams{
                Name:   "Normal Fin",
                Serial: "Right",
        }

        ctx, _ := context.WithCancel(context.Background())
        for i := 0; i <= 2000; i++ {
                components := componentSliceFixture()
        // update attribute for test
                components[0].Model = "test-" + strconv.Itoa(i)
                params.Model = components[0].Model

                fmt.Println(components[0].Model)

                //      update component
                _, err = s.Client.UpdateComponents(ctx, servers[0].UUID, components)
                assert.Nil(t, err)

                // list component updated
                got, _, err := s.Client.ListComponents(ctx, params)
                if err != nil {
                        t.Error(err)
                }

        // expect updated component to be returned
                assert.Len(t, got, 1)
                assert.Equal(t, components[0].Model, got[0].Model)
        }
}

enable debug mode in update method to dump sql query

func (r *Router) serverComponentUpdate(c *gin.Context) {
        boil.DebugMode = true
        defer func() { boil.DebugMode = false }()

run test

❯ /usr/local/bin/go test -timeout 30s -tags testtools -run ^TestLoopUpdate$ go.hollow.sh/serverservice/pkg/api/v1 -v
=== RUN   TestLoopUpdate
=== RUN   TestLoopUpdate/happy_path
=== RUN   TestLoopUpdate/invalid_auth_token
=== RUN   TestLoopUpdate/auth_token_with_no_scopes
=== RUN   TestLoopUpdate/fake_timeout
test-0
select * from "servers" where "id"=$1 and "deleted_at" is null
[65fd17a9-71f5-477f-8779-713101fbf14c]
select exists(select 1 from "server_components" where "id"=$1 limit 1)
41445f7c-e9b9-4678-bb78-927a8ab19cb1
UPDATE "server_components" SET "name"=$1,"vendor"=$2,"model"=$3,"serial"=$4,"server_component_type_id"=$5,"server_id"=$6,"updated_at"=$7 WHERE "id"=$8
[{Normal Fin true} { true} {test-0 true} {Left true} 2215fce6-7646-4053-89a8-67bae050d880 65fd17a9-71f5-477f-8779-713101fbf14c {2022-07-13 07:00:14.776816 +0000 UTC true} 41445f7c-e9b9-4678-bb78-927a8ab19cb1]
select exists(select 1 from "server_components" where "id"=$1 limit 1)
8fa91ee8-6a57-4d46-8697-ba9dee6802ec
UPDATE "server_components" SET "name"=$1,"vendor"=$2,"model"=$3,"serial"=$4,"server_component_type_id"=$5,"server_id"=$6,"updated_at"=$7 WHERE "id"=$8
[{Normal Fin true} { true} { true} {Right true} 2215fce6-7646-4053-89a8-67bae050d880 65fd17a9-71f5-477f-8779-713101fbf14c {2022-07-13 07:00:14.794443 +0000 UTC true} 8fa91ee8-6a57-4d46-8697-ba9dee6802ec]
=== CONT  TestLoopUpdate
    router_server_components_test.go:434:
                Error Trace:    router_server_components_test.go:434
                Error:          "[]" should have 1 item(s), but has 0
                Test:           TestLoopUpdate
--- FAIL: TestLoopUpdate (0.63s)
    --- PASS: TestLoopUpdate/happy_path (0.02s)
    --- PASS: TestLoopUpdate/invalid_auth_token (0.00s)
    --- PASS: TestLoopUpdate/auth_token_with_no_scopes (0.00s)
    --- PASS: TestLoopUpdate/fake_timeout (0.00s)
panic: runtime error: index out of range [0] with length 0 [recovered]
        panic: runtime error: index out of range [0] with length 0

goroutine 26 [running]:
testing.tRunner.func1.2({0x1a0eb80, 0xc0001284b0})
        /usr/local/Cellar/go/1.18.1/libexec/src/testing/testing.go:1389 +0x24e
testing.tRunner.func1()
        /usr/local/Cellar/go/1.18.1/libexec/src/testing/testing.go:1392 +0x39f
panic({0x1a0eb80, 0xc0001284b0})
        /usr/local/Cellar/go/1.18.1/libexec/src/runtime/panic.go:838 +0x207
go.hollow.sh/serverservice/pkg/api/v1_test.TestLoopUpdate(0xc000421860)
        /Users/jrebello/go/src/github.com/joelrebel/hollow-serverservice/pkg/api/v1/router_server_components_test.go:435 +0x4c5
testing.tRunner(0xc000421860, 0x1ae5b90)
        /usr/local/Cellar/go/1.18.1/libexec/src/testing/testing.go:1439 +0x102
created by testing.(*T).Run
        /usr/local/Cellar/go/1.18.1/libexec/src/testing/testing.go:1486 +0x35f
FAIL    go.hollow.sh/serverservice/pkg/api/v1   1.366s
FAIL

enable cockroach auth logs, sql execution logs

/usr/local/bin/cockroach sql --url "postgresql://root@localhost:26257/?sslmode=disable"   --insecure


root@localhost:26257/serverservice_test> SET CLUSTER SETTING server.auth_log.sql_connections.enabled=true;
SET CLUSTER SETTING

root@localhost:26257/defaultdb> SET CLUSTER SETTING sql.trace.log_statement_execute=true;
SET CLUSTER SETTING

❯ docker exec -ti 53aa0952d219 tail -f cockroach-data/logs/cockroach-sql-auth.log

I220713 06:46:54.606706 12452550 4@util/log/event_log.go:32 ⋮
[n1,client=‹172.22.0.1:60216›] 34
={"Timestamp":1657694814606688500,"EventType":"client_connection_start","InstanceID":1,"Network":"tcp","RemoteAddress":"‹172.22.0.1:60216›"}
I220713 06:46:54.957601 12452617 4@util/log/event_log.go:32 ⋮
[n1,client=‹172.22.0.1:60218›] 35
={"Timestamp":1657694814957583600,"EventType":"client_connection_start","InstanceID":1,"Network":"tcp","RemoteAddress":"‹172.22.0.1:60218›"}
I220713 06:46:55.271442 12452617 4@util/log/event_log.go:32 ⋮
[n1,client=‹172.22.0.1:60218›,hostnossl] 36
={"Timestamp":1657694815271423200,"EventType":"client_connection_end","InstanceID":1,"Network":"tcp","RemoteAddress":"‹172.22.0.1:60218›","Duration":313839600}
I220713 06:46:55.272470 12452550 4@util/log/event_log.go:32 ⋮
[n1,client=‹172.22.0.1:60216›,hostnossl] 37
={"Timestamp":1657694815272446300,"EventType":"client_connection_end","InstanceID":1,"Network":"tcp","RemoteAddress":"‹172.22.0.1:60216›","Duration":665757800}
^C

A failed update, select

docker exec -ti 53aa0952d219 tail -n 0 -f cockroach-data/logs/cockroach-sql-exec.log | grep 'test-'

I220713 07:17:45.721420 12485075 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:55636›,hostnossl,user=root] 1975 ={"Timestamp":1657696665718409000,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-0'›","‹'Left'›","‹'f940627a-8474-41c0-ab37-f4a810c97916'›","‹'84735c80-a711-4597-950e-1021b6376bc0'›","‹'2022-07-13 07:17:45.688831+00:00'›","‹'666a55ed-74ed-484a-aa62-705ec2524236'›"],"ExecMode":"exec","NumRows":1,"Age":3.1635,"TxnCounter":2}
I220713 07:17:46.752804 12485023 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:55634›,hostnossl,user=root] 1978 ={"Timestamp":1657696666748893500,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-0'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":4.1912,"FullTableScan":true,"TxnCounter":50}
I220713 07:17:46.759494 12485023 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:55634›,hostnossl,user=root] 1979 ={"Timestamp":1657696666756782500,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-0'›","‹'Right'›"],"ExecMode":"exec","Age":2.8987,"FullTableScan":true,"TxnCounter":51}

A successful update of 10 items

❯ docker exec -ti 53aa0952d219 tail -n 0 -f cockroach-data/logs/cockroach-sql-exec.log | grep 'test-'
I220713 07:21:55.693586 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3535 ={"Timestamp":1657696915690572800,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-0'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:55.683093+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":3.1143,"TxnCounter":2}
I220713 07:21:55.715837 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3538 ={"Timestamp":1657696915713834500,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-0'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.1364,"FullTableScan":true,"TxnCounter":50}
I220713 07:21:55.721582 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3539 ={"Timestamp":1657696915719081000,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-0'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.6206,"FullTableScan":true,"TxnCounter":51}
I220713 07:21:55.752041 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3545 ={"Timestamp":1657696915749553600,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-1'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:55.742428+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":2.582,"TxnCounter":6}
I220713 07:21:55.774153 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3548 ={"Timestamp":1657696915771635300,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-1'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.6623,"FullTableScan":true,"TxnCounter":57}
I220713 07:21:55.780711 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3549 ={"Timestamp":1657696915777957900,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-1'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.8461,"FullTableScan":true,"TxnCounter":58}
I220713 07:21:55.809979 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3555 ={"Timestamp":1657696915807643200,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-2'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:55.800696+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":2.431,"TxnCounter":10}
I220713 07:21:55.838839 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3558 ={"Timestamp":1657696915832586000,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-2'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":6.2945,"FullTableScan":true,"TxnCounter":64}
I220713 07:21:55.845040 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3559 ={"Timestamp":1657696915842783100,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-2'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.3382,"FullTableScan":true,"TxnCounter":65}
I220713 07:21:55.882080 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3565 ={"Timestamp":1657696915874378300,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-3'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:55.86617+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":8.2332,"TxnCounter":14}
I220713 07:21:55.912631 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3568 ={"Timestamp":1657696915909733700,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-3'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.973,"FullTableScan":true,"TxnCounter":71}
I220713 07:21:55.920684 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3569 ={"Timestamp":1657696915915975300,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-3'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":4.9702,"FullTableScan":true,"TxnCounter":72}
I220713 07:21:55.965015 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3575 ={"Timestamp":1657696915959731000,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-4'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:55.952113+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":5.4545,"TxnCounter":18}
I220713 07:21:55.994338 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3578 ={"Timestamp":1657696915992256800,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-4'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.3437,"FullTableScan":true,"TxnCounter":78}
I220713 07:21:56.000914 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3579 ={"Timestamp":1657696915997730200,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-4'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":3.3589,"FullTableScan":true,"TxnCounter":79}
I220713 07:21:56.036841 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3585 ={"Timestamp":1657696916033038000,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-5'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:56.025237+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":3.8902,"TxnCounter":22}
I220713 07:21:56.059760 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3588 ={"Timestamp":1657696916057644100,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-5'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.195,"FullTableScan":true,"TxnCounter":85}
I220713 07:21:56.065773 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3589 ={"Timestamp":1657696916063329800,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-5'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.5364,"FullTableScan":true,"TxnCounter":86}
I220713 07:21:56.097542 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3595 ={"Timestamp":1657696916094798500,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-6'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:56.087454+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":2.8332,"TxnCounter":26}
I220713 07:21:56.123277 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3598 ={"Timestamp":1657696916120473700,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-6'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.8855,"FullTableScan":true,"TxnCounter":92}
I220713 07:21:56.130017 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3599 ={"Timestamp":1657696916127289300,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-6'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.9743,"FullTableScan":true,"TxnCounter":93}
I220713 07:21:56.159947 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3605 ={"Timestamp":1657696916156940300,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-7'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:56.149524+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":3.0905,"TxnCounter":30}
I220713 07:21:56.185678 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3608 ={"Timestamp":1657696916182469600,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-7'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":3.3767,"FullTableScan":true,"TxnCounter":99}
I220713 07:21:56.192326 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3609 ={"Timestamp":1657696916189444100,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-7'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.9767,"FullTableScan":true,"TxnCounter":100}
I220713 07:21:56.219491 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3615 ={"Timestamp":1657696916216535600,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-8'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:56.208857+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":3.0426,"TxnCounter":34}
I220713 07:21:56.245130 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3618 ={"Timestamp":1657696916243097300,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-8'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.1101,"FullTableScan":true,"TxnCounter":106}
I220713 07:21:56.250304 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3619 ={"Timestamp":1657696916248289900,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-8'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.161,"FullTableScan":true,"TxnCounter":107}
I220713 07:21:56.295140 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3625 ={"Timestamp":1657696916291831800,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-9'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:56.282897+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":3.3575,"TxnCounter":38}
I220713 07:21:56.320503 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3628 ={"Timestamp":1657696916316995600,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-9'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":3.5888,"FullTableScan":true,"TxnCounter":113}
I220713 07:21:56.328491 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3629 ={"Timestamp":1657696916326386100,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-9'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.1897,"FullTableScan":true,"TxnCounter":114}
I220713 07:21:56.368319 12489922 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57888›,hostnossl,user=root] 3635 ={"Timestamp":1657696916365564300,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'test-10'›","‹'Right'›","‹'42d0fc33-e4c2-4e7c-8e55-911ca112ea71'›","‹'539d6c85-2344-4bbc-b62c-79ecc8f3ce2b'›","‹'2022-07-13 07:21:56.357923+00:00'›","‹'3314c271-acda-457a-961f-5e11480948b4'›"],"ExecMode":"exec","NumRows":1,"Age":2.8742,"TxnCounter":42}
I220713 07:21:56.395537 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3638 ={"Timestamp":1657696916393215600,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-10'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.4695,"FullTableScan":true,"TxnCounter":120}
I220713 07:21:56.402186 12489907 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.22.0.1:57886›,hostnossl,user=root] 3639 ={"Timestamp":1657696916399287300,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'test-10'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":2.954,"FullTableScan":true,"TxnCounter":121}
joelrebel commented

Heres a test that fails - the relevant lines in the logs are prefixed with >>>>>

Test output

❯ go test -timeout 30s -tags testtools -run ^TestIntegrationServerUpdateComponents$ go.hollow.sh/serverservice/pkg/api/v1 -v
=== RUN   TestIntegrationServerUpdateComponents
=== RUN   TestIntegrationServerUpdateComponents/real_client_-_happy_path
=== RUN   TestIntegrationServerUpdateComponents/real_client_-_invalid_auth_token
=== RUN   TestIntegrationServerUpdateComponents/real_client_-_auth_token_with_no_scopes
=== RUN   TestIntegrationServerUpdateComponents/real_client_-_fake_timeout
=== RUN   TestIntegrationServerUpdateComponents/component_update_on_versioned_attributes
select * from "servers" where "id"=$1 and "deleted_at" is null
[153e9eb0-2309-43ad-8a46-3167fe058c97]
select exists(select 1 from "server_components" where "id"=$1 limit 1)
15e8b2bd-9775-4494-a63f-4918ddf47ef8
UPDATE "server_components" SET "name"=$1,"vendor"=$2,"model"=$3,"serial"=$4,"server_component_type_id"=$5,"server_id"=$6,"updated_at"=$7 WHERE "id"=$8
[{Normal Fin true} { true} {testUpdatedVA true} {Left true} 20697000-657e-4716-8891-5520ccef5a22 153e9eb0-2309-43ad-8a46-3167fe058c97 {2022-07-28 13:47:38.451334 +0000 UTC true} 15e8b2bd-9775-4494-a63f-4918ddf47ef8]
INSERT INTO "versioned_attributes" ("namespace","data","created_at","updated_at","server_component_id") VALUES ($1,$2,$3,$4,$5) RETURNING "id","server_id","tally"
[hollow.metadata {"version":"1.12345"} {2022-07-28 13:47:38.458276 +0000 UTC true} {2022-07-28 13:47:38.458276 +0000 UTC true} {15e8b2bd-9775-4494-a63f-4918ddf47ef8 true}]
select exists(select 1 from "server_components" where "id"=$1 limit 1)
d1605998-86e3-4752-a6b7-6955351a40a3
UPDATE "server_components" SET "name"=$1,"vendor"=$2,"model"=$3,"serial"=$4,"server_component_type_id"=$5,"server_id"=$6,"updated_at"=$7 WHERE "id"=$8
[{Normal Fin true} { true} { true} {Right true} 20697000-657e-4716-8891-5520ccef5a22 153e9eb0-2309-43ad-8a46-3167fe058c97 {2022-07-28 13:47:38.472329 +0000 UTC true} d1605998-86e3-4752-a6b7-6955351a40a3]
SELECT COUNT(*) FROM "server_components" WHERE (server_components.name = $1 AND server_components.model = $2 AND server_components.serial = $3);
[Normal Fin testUpdatedVA Right]

>>>>>>> \/\/\/\/\/\/ The select that returns no rows, causing the test to fail \/\/\/\/
SELECT "server_components".* FROM "server_components" WHERE (server_components.name = $1 AND server_components.model = $2 AND server_components.serial = $3) ORDER BY server_components.created_at DESC LIMIT 100;
[Normal Fin testUpdatedVA Right]



    router_server_components_test.go:715:
                Error Trace:    /Users/jrebello/go/src/github.com/joelrebel/hollow-serverservice/pkg/api/v1/router_server_components_test.go:715
                Error:          "[]" should have 1 item(s), but has 0
                Test:           TestIntegrationServerUpdateComponents/component_update_on_versioned_attributes
--- FAIL: TestIntegrationServerUpdateComponents (1.02s)
    --- PASS: TestIntegrationServerUpdateComponents/real_client_-_happy_path (0.08s)
    --- PASS: TestIntegrationServerUpdateComponents/real_client_-_invalid_auth_token (0.00s)
    --- PASS: TestIntegrationServerUpdateComponents/real_client_-_auth_token_with_no_scopes (0.00s)
    --- PASS: TestIntegrationServerUpdateComponents/real_client_-_fake_timeout (0.00s)
    --- FAIL: TestIntegrationServerUpdateComponents/component_update_on_versioned_attributes (0.06s)
panic: runtime error: index out of range [0] with length 0 [recovered]
        panic: runtime error: index out of range [0] with length 0

goroutine 68 [running]:
testing.tRunner.func1.2({0x1b0dea0, 0xc000324d68})
        /usr/local/Cellar/go/1.18.1/libexec/src/testing/testing.go:1389 +0x24e
testing.tRunner.func1()
        /usr/local/Cellar/go/1.18.1/libexec/src/testing/testing.go:1392 +0x39f
panic({0x1b0dea0, 0xc000324d68})
        /usr/local/Cellar/go/1.18.1/libexec/src/runtime/panic.go:838 +0x207
go.hollow.sh/serverservice/pkg/api/v1_test.TestIntegrationServerUpdateComponents.func3(0xc000581520)
        /Users/jrebello/go/src/github.com/joelrebel/hollow-serverservice/pkg/api/v1/router_server_components_test.go:716 +0x77d
testing.tRunner(0xc000581520, 0xc0000d85e8)
        /usr/local/Cellar/go/1.18.1/libexec/src/testing/testing.go:1439 +0x102
created by testing.(*T).Run
        /usr/local/Cellar/go/1.18.1/libexec/src/testing/testing.go:1486 +0x35f
FAIL    go.hollow.sh/serverservice/pkg/api/v1   1.635s
FAIL

crdb sql execution log

I220728 13:47:38.394948 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 264 ={"Timestamp":1659016058393346500,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".attributes WHERE (attributes.server_id IN ($1, $2, $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'153e9eb0-2309-43ad-8a46-3167fe058c97'›","‹'c45249fe-24df-4a2b-a044-dde122b0989a'›","‹'bfb6abb2-bc44-4eb3-b3f9-487fdb82e4c5'›"],"ExecMode":"exec","NumRows":6,"Age":1.686,"TxnCounter":42}
I220728 13:47:38.403370 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 265 ={"Timestamp":1659016058398776600,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".versioned_attributes WHERE (versioned_attributes.server_id IN ($1, $2, $3)) AND ((server_id, namespace, created_at) IN (SELECT server_id, namespace, max(created_at) FROM \"\".\"\".versioned_attributes GROUP BY server_id, namespace))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'153e9eb0-2309-43ad-8a46-3167fe058c97'›","‹'c45249fe-24df-4a2b-a044-dde122b0989a'›","‹'bfb6abb2-bc44-4eb3-b3f9-487fdb82e4c5'›"],"ExecMode":"exec","NumRows":2,"Age":4.7985,"FullIndexScan":true,"TxnCounter":43}
I220728 13:47:38.408567 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 266 ={"Timestamp":1659016058407011700,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (server_components.server_id IN ($1, $2, $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'153e9eb0-2309-43ad-8a46-3167fe058c97'›","‹'c45249fe-24df-4a2b-a044-dde122b0989a'›","‹'bfb6abb2-bc44-4eb3-b3f9-487fdb82e4c5'›"],"ExecMode":"exec","NumRows":6,"Age":1.675,"TxnCounter":44}
I220728 13:47:38.422086 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 267 ={"Timestamp":1659016058412859100,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".attributes WHERE (attributes.server_component_id IN ($1, $2, $3, $4, $5, $6))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'15e8b2bd-9775-4494-a63f-4918ddf47ef8'›","‹'d1605998-86e3-4752-a6b7-6955351a40a3'›","‹'09ce5618-fea6-41c9-aab1-80b0b9570898'›","‹'4fe0e7eb-63b6-4f61-a963-af7a967d9a1d'›","‹'1c2c552d-8818-4ca1-b352-fde84d928430'›","‹'96b3747f-9c01-4e25-a98c-2f82d6124be2'›"],"ExecMode":"exec","Age":9.7584,"FullIndexScan":true,"TxnCounter":45}
I220728 13:47:38.428580 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 268 ={"Timestamp":1659016058427314100,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_component_types WHERE (server_component_types.id IN ($1,))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'20697000-657e-4716-8891-5520ccef5a22'›"],"ExecMode":"exec","NumRows":1,"Age":1.5838,"TxnCounter":46}
I220728 13:47:38.435714 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 269 ={"Timestamp":1659016058433830800,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".servers WHERE (id = $1) AND (deleted_at IS NULL)›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'bfb6abb2-bc44-4eb3-b3f9-487fdb82e4c5'›"],"ExecMode":"exec","NumRows":1,"Age":1.8295,"TxnCounter":47}
I220728 13:47:38.442537 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 270 ={"Timestamp":1659016058438100400,"EventType":"query_execute","Statement":"‹SELECT EXISTS (SELECT 1 FROM \"\".\"\".server_components WHERE id = $1 LIMIT 1)›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'15e8b2bd-9775-4494-a63f-4918ddf47ef8'›"],"ExecMode":"exec","NumRows":1,"Age":1.1646,"TxnCounter":48}
I220728 13:47:38.451179 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 271 ={"Timestamp":1659016058438100400,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'Normal Fin'›","‹'lala'›","‹'20697000-657e-4716-8891-5520ccef5a22'›","‹'bfb6abb2-bc44-4eb3-b3f9-487fdb82e4c5'›","‹'2022-07-28 13:47:38.41763+00:00'›","‹'15e8b2bd-9775-4494-a63f-4918ddf47ef8'›"],"ExecMode":"exec","NumRows":1,"Age":5.4491,"TxnCounter":48}
I220728 13:47:38.468677 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 272 ={"Timestamp":1659016058467723100,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".servers WHERE (id = $1) AND (deleted_at IS NULL)›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'153e9eb0-2309-43ad-8a46-3167fe058c97'›"],"ExecMode":"exec","NumRows":1,"Age":1.0266,"TxnCounter":49}
I220728 13:47:38.475125 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 273 ={"Timestamp":1659016058470492100,"EventType":"query_execute","Statement":"‹SELECT EXISTS (SELECT 1 FROM \"\".\"\".server_components WHERE id = $1 LIMIT 1)›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'15e8b2bd-9775-4494-a63f-4918ddf47ef8'›"],"ExecMode":"exec","NumRows":1,"Age":1.2233,"TxnCounter":50}
I220728 13:47:38.482620 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 274 ={"Timestamp":1659016058470492100,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'testUpdatedVA'›","‹'Left'›","‹'20697000-657e-4716-8891-5520ccef5a22'›","‹'153e9eb0-2309-43ad-8a46-3167fe058c97'›","‹'2022-07-28 13:47:38.451334+00:00'›","‹'15e8b2bd-9775-4494-a63f-4918ddf47ef8'›"],"ExecMode":"exec","NumRows":1,"Age":3.2797,"TxnCounter":50}
I220728 13:47:38.490003 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 275 ={"Timestamp":1659016058470492100,"EventType":"query_execute","Statement":"‹INSERT INTO \"\".\"\".versioned_attributes(namespace, data, created_at, updated_at, server_component_id) VALUES ($1, $2, $3, $4, $5) RETURNING id, server_id, tally›","Tag":"INSERT","User":"root","PlaceholderValues":["‹'hollow.metadata'›","‹'{\"version\": \"1.12345\"}'›","‹'2022-07-28 13:47:38.458276+00:00'›","‹'2022-07-28 13:47:38.458276+00:00'›","‹'15e8b2bd-9775-4494-a63f-4918ddf47ef8'›"],"ExecMode":"exec","NumRows":1,"Age":3.2637,"TxnCounter":50}
I220728 13:47:38.497283 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 276 ={"Timestamp":1659016058470492100,"EventType":"query_execute","Statement":"‹SELECT EXISTS (SELECT 1 FROM \"\".\"\".server_components WHERE id = $1 LIMIT 1)›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'d1605998-86e3-4752-a6b7-6955351a40a3'›"],"ExecMode":"exec","NumRows":1,"Age":1.2005,"TxnCounter":50}
I220728 13:47:38.503552 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 277 ={"Timestamp":1659016058470492100,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹''›","‹'Right'›","‹'20697000-657e-4716-8891-5520ccef5a22'›","‹'153e9eb0-2309-43ad-8a46-3167fe058c97'›","‹'2022-07-28 13:47:38.472329+00:00'›","‹'d1605998-86e3-4752-a6b7-6955351a40a3'›"],"ExecMode":"exec","NumRows":1,"Age":3.3206,"TxnCounter":50}
I220728 13:47:38.518500 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 278 ={"Timestamp":1659016058517036700,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'testUpdatedVA'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":1.4951,"FullTableScan":true,"TxnCounter":51}



>>>>>>> \/\/\/\/\/\/ The select that returns no rows, causing the test to fail - (NumRows nil) \/\/\/\/
I220728 13:47:38.524652 65232 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:55174›,hostnossl,user=root] 279 ={"Timestamp":1659016058523002100,"EventType":"query_execute","Statement":"‹SELECT server_components.* FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'testUpdatedVA'›","‹'Right'›"],"ExecMode":"exec","Age":1.7048,"FullTableScan":true,"TxnCounter":52}
joelrebel commented

And heres the same test that suceeded in a subsequent run

Test output

❯ go test -timeout 30s -tags testtools -run ^TestIntegrationServerUpdateComponents$ go.hollow.sh/serverservice/pkg/api/v1 -v
=== RUN   TestIntegrationServerUpdateComponents
=== RUN   TestIntegrationServerUpdateComponents/real_client_-_happy_path
=== RUN   TestIntegrationServerUpdateComponents/real_client_-_invalid_auth_token
=== RUN   TestIntegrationServerUpdateComponents/real_client_-_auth_token_with_no_scopes
=== RUN   TestIntegrationServerUpdateComponents/real_client_-_fake_timeout
=== RUN   TestIntegrationServerUpdateComponents/component_update_on_versioned_attributes
select * from "servers" where "id"=$1 and "deleted_at" is null
[3451eeeb-0814-4fd4-b028-2ecf671b467f]
select exists(select 1 from "server_components" where "id"=$1 limit 1)
a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7
UPDATE "server_components" SET "name"=$1,"vendor"=$2,"model"=$3,"serial"=$4,"server_component_type_id"=$5,"server_id"=$6,"updated_at"=$7 WHERE "id"=$8
[{Normal Fin true} { true} {testUpdatedVA true} {Right true} c5887de7-22ee-4246-9b4c-d1c0d8e1507b 3451eeeb-0814-4fd4-b028-2ecf671b467f {2022-07-28 13:57:15.744594 +0000 UTC true} a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7]
INSERT INTO "versioned_attributes" ("namespace","data","created_at","updated_at","server_component_id") VALUES ($1,$2,$3,$4,$5) RETURNING "id","server_id","tally"
[hollow.metadata {"version":"1.12345"} {2022-07-28 13:57:15.756001 +0000 UTC true} {2022-07-28 13:57:15.756001 +0000 UTC true} {a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7 true}]
select exists(select 1 from "server_components" where "id"=$1 limit 1)
dc262929-0844-475e-bd40-0bba735cd503
UPDATE "server_components" SET "name"=$1,"vendor"=$2,"model"=$3,"serial"=$4,"server_component_type_id"=$5,"server_id"=$6,"updated_at"=$7 WHERE "id"=$8
[{Normal Fin true} { true} {Normal Fin true} {Left true} c5887de7-22ee-4246-9b4c-d1c0d8e1507b 3451eeeb-0814-4fd4-b028-2ecf671b467f {2022-07-28 13:57:15.770147 +0000 UTC true} dc262929-0844-475e-bd40-0bba735cd503]
SELECT COUNT(*) FROM "server_components" WHERE (server_components.name = $1 AND server_components.model = $2 AND server_components.serial = $3);
[Normal Fin testUpdatedVA Right]

>>>>>>> \/\/\/\/\/\/ The select that succeeds here (that fails intermittently)  \/\/\/\/

SELECT "server_components".* FROM "server_components" WHERE (server_components.name = $1 AND server_components.model = $2 AND server_components.serial = $3) ORDER BY server_components.created_at DESC LIMIT 100;
[Normal Fin testUpdatedVA Right]

SELECT * FROM "attributes" WHERE ("attributes"."server_component_id" IN ($1));
[a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7]
SELECT * FROM "versioned_attributes" WHERE ("versioned_attributes"."server_component_id" IN ($1)) AND ((server_component_id, namespace, created_at) IN (select server_component_id, namespace, max(created_at) from versioned_attributes group by server_component_id, namespace));
[a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7]
SELECT * FROM "server_component_types" WHERE ("server_component_types"."id" IN ($1));
[c5887de7-22ee-4246-9b4c-d1c0d8e1507b]
--- PASS: TestIntegrationServerUpdateComponents (1.00s)
    --- PASS: TestIntegrationServerUpdateComponents/real_client_-_happy_path (0.08s)
    --- PASS: TestIntegrationServerUpdateComponents/real_client_-_invalid_auth_token (0.00s)
    --- PASS: TestIntegrationServerUpdateComponents/real_client_-_auth_token_with_no_scopes (0.00s)
    --- PASS: TestIntegrationServerUpdateComponents/real_client_-_fake_timeout (0.00s)
    --- PASS: TestIntegrationServerUpdateComponents/component_update_on_versioned_attributes (0.09s)
PASS
ok      go.hollow.sh/serverservice/pkg/api/v1   1.404s

crdb sql execution log

I220728 13:57:15.687312 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 901 ={"Timestamp":1659016635684752900,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".servers WHERE (servers.deleted_at IS NULL)›","Tag":"SELECT","User":"root","ExecMode":"exec","NumRows":1,"Age":2.9293,"FullTableScan":true,"TxnCounter":40}
I220728 13:57:15.693477 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 902 ={"Timestamp":1659016635691031000,"EventType":"query_execute","Statement":"‹SELECT DISTINCT servers.* FROM \"\".\"\".servers WHERE (servers.deleted_at IS NULL) ORDER BY servers.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","ExecMode":"exec","NumRows":3,"Age":3.1052,"FullTableScan":true,"TxnCounter":41}
I220728 13:57:15.701371 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 903 ={"Timestamp":1659016635699640600,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".attributes WHERE (attributes.server_id IN ($1, $2, $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'3451eeeb-0814-4fd4-b028-2ecf671b467f'›","‹'15c87c86-78dd-45c8-9897-cf3ff3fe3e87'›","‹'3e5ae35f-42a7-42a1-a8c6-f09ce8e34ceb'›"],"ExecMode":"exec","NumRows":6,"Age":1.9355,"TxnCounter":42}
I220728 13:57:15.710786 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 904 ={"Timestamp":1659016635706878200,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".versioned_attributes WHERE (versioned_attributes.server_id IN ($1, $2, $3)) AND ((server_id, namespace, created_at) IN (SELECT server_id, namespace, max(created_at) FROM \"\".\"\".versioned_attributes GROUP BY server_id, namespace))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'3451eeeb-0814-4fd4-b028-2ecf671b467f'›","‹'15c87c86-78dd-45c8-9897-cf3ff3fe3e87'›","‹'3e5ae35f-42a7-42a1-a8c6-f09ce8e34ceb'›"],"ExecMode":"exec","NumRows":2,"Age":4.0623,"FullIndexScan":true,"TxnCounter":43}
I220728 13:57:15.717636 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 905 ={"Timestamp":1659016635714443800,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_components WHERE (server_components.server_id IN ($1, $2, $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'3451eeeb-0814-4fd4-b028-2ecf671b467f'
 ","‹'15c87c86-78dd-45c8-9897-cf3ff3fe3e87'›","‹'3e5ae35f-42a7-42a1-a8c6-f09ce8e34ceb'›"],"ExecMode":"exec","NumRows":6,"Age":3.2908,"TxnCounter":44}
I220728 13:57:15.723243 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 906 ={"Timestamp":1659016635721249300,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".attributes WHERE (attributes.server_component_id IN ($1, $2, $3, $4, $5, $6))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7'›","‹'dc262929-0844-475e-bd40-0bba735cd503'›","‹'f1b20852-884c-4b31-af69-cc36de931190'›","‹'f82cf9d6-646a-4d37-9cb4-b7051da23819'›","‹'02e71fc4-1229-4ae9-9ec3-92b9536f7532'›","‹'8116acba-9963-4867-bc41-d84bd700b588'›"],"ExecMode":"exec","Age":2.0968,"FullIndexScan":true,"TxnCounter":45}
I220728 13:57:15.728927 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 907 ={"Timestamp":1659016635727380500,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_component_types WHERE (server_component_types.id IN ($1,))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'c5887de7-22ee-4246-9b4c-d1c0d8e1507b'›"],"ExecMode":"exec","NumRows":1,"Age":1.7639,"TxnCounter":46}
I220728 13:57:15.735281 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 908 ={"Timestamp":1659016635733849100,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".servers WHERE (id = $1) AND (deleted_at IS NULL)›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'3e5ae35f-42a7-42a1-a8c6-f09ce8e34ceb'›"],"ExecMode":"exec","NumRows":1,"Age":1.6443,"TxnCounter":47}
I220728 13:57:15.742676 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 909 ={"Timestamp":1659016635737971500,"EventType":"query_execute","Statement":"‹SELECT EXISTS (SELECT 1 FROM \"\".\"\".server_components WHERE id = $1 LIMIT 1)›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7'›"],"ExecMode":"exec","NumRows":1,"Age":1.6093,"TxnCounter":48}
I220728 13:57:15.750055 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 910 ={"Timestamp":1659016635737971500,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹''›","‹'lala'›","‹'c5887de7-22ee-4246-9b4c-d1c0d8e1507b'›","‹'3e5ae35f-42a7-42a1-a8c6-f09ce8e34ceb'›","‹'2022-07-28 13:57:15.709907+00:00'›","‹'a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7'›"],"ExecMode":"exec","NumRows":1,"Age":3.9041,"TxnCounter":48}
I220728 13:57:15.769556 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 911 ={"Timestamp":1659016635768299800,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".servers WHERE (id = $1) AND (deleted_at IS NULL)›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'3451eeeb-0814-4fd4-b028-2ecf671b467f'›"],"ExecMode":"exec","NumRows":1,"Age":1.3657,"TxnCounter":49}
I220728 13:57:15.777570 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 912 ={"Timestamp":1659016635771536100,"EventType":"query_execute","Statement":"‹SELECT EXISTS (SELECT 1 FROM \"\".\"\".server_components WHERE id = $1 LIMIT 1)›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7'›"],"ExecMode":"exec","NumRows":1,"Age":1.2456,"TxnCounter":50}
I220728 13:57:15.788871 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 913 ={"Timestamp":1659016635771536100,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'testUpdatedVA'›","‹'Right'›","‹'c5887de7-22ee-4246-9b4c-d1c0d8e1507b'›","‹'3451eeeb-0814-4fd4-b028-2ecf671b467f'›","‹'2022-07-28 13:57:15.744594+00:00'›","‹'a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7'›"],"ExecMode":"exec","NumRows":1,"Age":7.7751,"TxnCounter":50}
I220728 13:57:15.797079 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 914 ={"Timestamp":1659016635771536100,"EventType":"query_execute","Statement":"‹INSERT INTO \"\".\"\".versioned_attributes(namespace, data, created_at, updated_at, server_component_id) VALUES ($1, $2, $3, $4, $5) RETURNING id, server_id, tally›","Tag":"INSERT","User":"root","PlaceholderValues":["‹'hollow.metadata'›","‹'{\"version\": \"1.12345\"}'›","‹'2022-07-28 13:57:15.756001+00:00'›","‹'2022-07-28 13:57:15.756001+00:00'›","‹'a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7'›"],"ExecMode":"exec","NumRows":1,"Age":3.9477,"TxnCounter":50}
I220728 13:57:15.802994 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 915 ={"Timestamp":1659016635771536100,"EventType":"query_execute","Statement":"‹SELECT EXISTS (SELECT 1 FROM \"\".\"\".server_components WHERE id = $1 LIMIT 1)›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'dc262929-0844-475e-bd40-0bba735cd503'›"],"ExecMode":"exec","NumRows":1,"Age":1.2714,"TxnCounter":50}
I220728 13:57:15.812538 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 916 ={"Timestamp":1659016635771536100,"EventType":"query_execute","Statement":"‹UPDATE \"\".\"\".server_components SET name = $1, vendor = $2, model = $3, serial = $4, server_component_type_id = $5, server_id = $6, updated_at = $7 WHERE id = $8›","Tag":"UPDATE","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹''›","‹'Normal Fin'›","‹'Left'›","‹'c5887de7-22ee-4246-9b4c-d1c0d8e1507b'›","‹'3451eeeb-0814-4fd4-b028-2ecf671b467f'›","‹'2022-07-28 13:57:15.770147+00:00'›","‹'dc262929-0844-475e-bd40-0bba735cd503'›"],"ExecMode":"exec","NumRows":1,"Age":5.4433,"TxnCounter":50}
I220728 13:57:15.826886 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 917 ={"Timestamp":1659016635825616900,"EventType":"query_execute","Statement":"‹SELECT count(*) FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'testUpdatedVA'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":1.4067,"FullTableScan":true,"TxnCounter":51}
I220728 13:57:15.831348 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 918 ={"Timestamp":1659016635830032200,"EventType":"query_execute","Statement":"‹SELECT server_components.* FROM \"\".\"\".server_components WHERE (((server_components.name = $1) AND (server_components.model = $2)) AND (server_components.serial = $3)) ORDER BY server_components.created_at DESC LIMIT 100›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'Normal Fin'›","‹'testUpdatedVA'›","‹'Right'›"],"ExecMode":"exec","NumRows":1,"Age":1.4083,"FullTableScan":true,"TxnCounter":52}
I220728 13:57:15.841141 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 919 ={"Timestamp":1659016635836961400,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".attributes WHERE (attributes.server_component_id IN ($1,))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7'›"],"ExecMode":"exec","Age":5.9069,"TxnCounter":53}
I220728 13:57:15.849720 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 920 ={"Timestamp":1659016635845833500,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".versioned_attributes WHERE (versioned_attributes.server_component_id IN ($1,)) AND ((server_component_id, namespace, created_at) IN (SELECT server_component_id, namespace, max(created_at) FROM \"\".\"\".versioned_attributes GROUP BY server_component_id, namespace))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'a4ee511f-1eb0-4f6d-89af-d55bfcee3eb7'›"],"ExecMode":"exec","NumRows":1,"Age":4.1538,"TxnCounter":54}



>>>>>>> \/\/\/\/\/\/ The select that succeeds here (that fails intermittently)  \/\/\/\/

I220728 13:57:15.854900 73216 9@util/log/event_log.go:32 ⋮ [n1,client=‹172.23.0.1:60610›,hostnossl,user=root] 921 ={"Timestamp":1659016635853422900,"EventType":"query_execute","Statement":"‹SELECT * FROM \"\".\"\".server_component_types WHERE (server_component_types.id IN ($1,))›","Tag":"SELECT","User":"root","PlaceholderValues":["‹'c5887de7-22ee-4246-9b4c-d1c0d8e1507b'›"],"ExecMode":"exec","NumRows":1,"Age":1.5708,"TxnCounter":55}
joelrebel commented

After some amount of poking around, the test fixtures used were not consistent and so different across runs depending on the order returned by the server lookup. So nothing too crazy to see here.