Currency tests failing sporadically #722

dbemiller · 2018-10-23T14:55:50Z

I saw lots of errors like this while running ./validate.sh locally. There seem to be two unrelated problems.

The first is an os.SyscallError when trying to fetch conversion rates:

        	Error Trace:	rate_converter_test.go:526
        	            				asm_amd64.s:1333
        	Error:      	Expected nil, but got: &url.Error{Op:"Get", URL:"http://127.0.0.1:53676", Err:(*net.OpError)(0xc0004c2000)}
        	Test:       	TestRace
        	Messages:   	root error was: connect: can't assign requested address

This is on a Macbook Pro. The message: root error was: connect: can't assign requested address comes from some custom code I added to unwrap the net.OpError that shows up as a pointer in the original message.

I suspect Travis didn't have these because it runs tests on a different OS.

The second does not reproduce consistently... but it's not rare either. I suspect Travis didn't catch it because the failures are intermittent.

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x1409538]

goroutine 136136 [running]:
github.com/prebid/prebid-server/currencies.(*Rates).GetRate(0x0, 0x14de558, 0x3, 0x14de4fe, 0x3, 0x4, 0xc00048cef0, 0x10784df)
	/Users/dbemiller/go/src/github.com/prebid/prebid-server/currencies/rates.go:47 +0x48
github.com/prebid/prebid-server/currencies_test.TestRace.func2(0xc0006a8b40, 0xc0001ce500, 0xc00009c8f0, 0xc000180300, 0x0)
	/Users/dbemiller/go/src/github.com/prebid/prebid-server/currencies/rate_converter_test.go:525 +0x303
created by github.com/prebid/prebid-server/currencies_test.TestRace
	/Users/dbemiller/go/src/github.com/prebid/prebid-server/currencies/rate_converter_test.go:512 +0x227
FAIL	github.com/prebid/prebid-server/currencies	20.826s

This is probably due to a race condition that the race detector doesn't pick up, but nevertheless exists.

I'm not sure whether or not these are expected... but I'll put them down here as extra info. There are a big string of log messages before the test finally fails:

E1023 09:38:02.214017    6796 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
E1023 09:38:02.215448    6796 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
E1023 09:38:02.215586    6796 rate_converter.go:105] Error updating conversion rates: Get justaweirdurl: unsupported protocol scheme ""
E1023 09:38:02.215915    6796 rate_converter.go:105] Error updating conversion rates: invalid character '}' after object key
E1023 09:38:02.216275    6796 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
E1023 09:38:05.027268    6796 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
E1023 09:38:12.389122    6796 rate_converter.go:105] Error updating conversion rates: Get http://127.0.0.1:64445: dial tcp 127.0.0.1:64445: connect: can't assign requested address
E1023 09:38:12.463195    6796 rate_converter.go:105] Error updating conversion rates: Get http://127.0.0.1:64445: dial tcp 127.0.0.1:64445: connect: can't assign requested address
E1023 09:38:12.471708    6796 rate_converter.go:105] Error updating conversion rates: Get http://127.0.0.1:64445: dial tcp 127.0.0.1:64445: connect: can't assign requested address
E1023 09:38:12.473485    6796 rate_converter.go:105] Error updating conversion rates: Get http://127.0.0.1:64445: dial tcp 127.0.0.1:64445: connect: can't assign requested address
E1023 09:38:12.473489    6796 rate_converter.go:105] Error updating conversion rates: Get http://127.0.0.1:64445: dial tcp 127.0.0.1:64445: connect: can't assign requested address
E1023 09:38:12.473559    6796 rate_converter.go:105] Error updating conversion rates: Get http://127.0.0.1:64445: dial tcp 127.0.0.1:64445: connect: can't assign requested address
E1023 09:38:12.475213    6796 rate_converter.go:105] Error updating conversion rates: Get http://127.0.0.1:64445: dial tcp 127.0.0.1:64445: connect: can't assign requested address

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

dbemiller · 2018-10-23T14:56:41Z

To reproduce locally, run this. It might take a few tries:

go test -race github.com/prebid/prebid-server/currencies -run ^TestRace.*$ -count 5

dbemiller · 2018-10-23T17:02:17Z

Updated the original comment with better info. For now this has been removed through #723 because master should always be clean.

hhhjort · 2018-10-23T17:19:11Z

I believe the problem with failed http requests stems from concurrent requests to the mock server. If you lower the number of workers/interval frequency to insure that one call to the mock server completes before the next time it is called, will that mean we have essentially lowered the race condition test to effectively a single threaded entity? I expect the http processing through the loop back device makes the http call the longest process running. If that never overlaps itself, how often do we expect that processing the rates will land just on the border of the rate update and thus exercise the race condition potential?

I would rather see a solution where the rate of currency conversions isn't limited to match the rate of sequential calls to update the rates. Perhaps have one goroutine run a tight loop calling the mock server, and a collection of other goroutines calling for rate conversions only. The code already limits to only one update call at a time, so no need to allow two updates to try to process concurrently.

dbemiller · 2018-10-23T17:19:19Z

One easy way to fix the server connection issue is to send a mock version of the currencies.httpClient interface. For example:

type mockClient struct {
	responseBody string
}

func (m *mockClient) Do(req *http.Request) (*http.Response, error) {
	return &http.Response{
		Status:     "200 OK",
		StatusCode: http.StatusOK,
		Body:       ioutil.NopCloser(strings.NewReader(m.responseBody)),
	}, nil
}

Send this into currencies.NewRateConverter(), and you can bypass the httptest.NewServer() calls altogether.

benjaminch · 2018-10-23T19:19:16Z

Hey @dbemiller and @hhhjort,

Sorry for this one.

First regarding

E1023 09:38:02.214017    6796 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
E1023 09:38:02.215448    6796 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
E1023 09:38:02.215586    6796 rate_converter.go:105] Error updating conversion rates: Get justaweirdurl: unsupported protocol scheme ""
E1023 09:38:02.215915    6796 rate_converter.go:105] Error updating conversion rates: invalid character '}' after object key
E1023 09:38:02.216275    6796 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
E1023 09:38:05.027268    6796 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input

Those warnings are expected since those relate to either bad JSON or bad URL test, so looks normal to me.

Regarding the others

E1023 09:38:12.389122    6796 rate_converter.go:105] Error updating conversion rates: Get http://127.0.0.1:64445: dial tcp 127.0.0.1:64445: connect: can't assign requested address

are indeed an issue.

Regarding

One easy way to fix the server connection issue is to send a mock version of the currencies.httpClient interface.

I did that before but moved to httptest lib instead not to have to create a mock following
a comment in #705.
I can reintroduce it to test :)

dbemiller · 2018-10-23T19:28:31Z

No worries at all. Re: log messages, that makes a lot of sense.

I talked to @hhhjort here too, and had another suggestion. Basically just limit "updates" to a single goroutine, but still have many Readers. This should stop the OS from getting overloaded with connections (although I didn't test it), and more closely matches how prod would work anyway.

There are some tradeoffs to each option... so both sound fine to me as long as they check the concurrency & pass reliably.

benjaminch · 2018-10-23T19:45:52Z

Ok, I will test the later option and keep you posted, I will launch test on a test computer here as well.
Indeed, in production, there should be only one updater and might have many readers.
Maybe the test method was indeed a bit to aggressive, too many updaters and a very short update interval which definitively not represents the reality.

Maybe we can try to keep couple readers because an Update can be triggered manually from outside but make the update intervals closer to the reality (1 second or so) so it won't overlap with any other update.

Do you think we need to introduce a system to prevent such httpClient overload by maybe:

Prevent having to Update / Fetch happening at the same time (via a lock) ?
Having a min interval duration value higher than 5 seconds ?

benjaminch · 2018-10-23T19:58:23Z

And indeed, using an HttpClientMock does the trick. I don't see any warnings / errors locally but only warnings regarding bad JSONs and bad URLs.

➜ go test
E1023 21:55:35.485616   67401 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
E1023 21:55:35.487093   67401 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
E1023 21:55:35.487237   67401 rate_converter.go:105] Error updating conversion rates: Get justaweirdurl: unsupported protocol scheme ""
E1023 21:55:35.487728   67401 rate_converter.go:105] Error updating conversion rates: invalid character '}' after object key
E1023 21:55:35.488266   67401 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
E1023 21:55:38.317488   67401 rate_converter.go:105] Error updating conversion rates: unexpected end of JSON input
PASS
ok      github.com/prebid/prebid-server/currencies      12.855s

dbemiller · 2018-10-23T19:59:59Z

No. The atomic.Value is the lock. The test must read & write concurrently, without locks, so that the race detector can do its job.

It's also a good thing that you're doing lots of reads & writes in a short time. The more reads & writes in a short time, the better chance your code exhibits "race-y" behavior that the race detector can catch.

Limiting writes to one goroutine is just a compromise to work around this connection issue. It's actually less likely to stumble on race conditions this way... but since it'd still be doing concurrent reads & writes, the test would still add value because the chance is non-zero.

benjaminch · 2018-10-23T20:08:11Z

Well, as you guys prefer, I personally kind of like having an HTTPClientMock taking no time for this test and have a lot of writers / readers so it really tests the concurrency.

If you prefer having only one writer for this test I am also ok with it but I feel like it might not represent the real usage.

dbemiller · 2018-10-23T20:15:14Z

both are fine :)

hhhjort · 2018-10-23T20:20:10Z

Both are fine with me as well.

This CL introduces a mechanism to fetch currencies rates periodically from a remote source. Those rates are stored in `CurrencyConverter` struct which can be injected in PBS to get rates. This doesn't introduce any changes in PBS workflow just yet. It also address issues described in prebid#722 regarding httptestClient overload in tests generating errors while running `validate.sh` script. Issue: prebid#280

This CL introduces a mechanism to fetch currencies rates periodically from a remote source. Those rates are stored in `CurrencyConverter` struct which can be injected in PBS to get rates. This doesn't introduce any changes in PBS workflow just yet. It also address issues described in #722 regarding httptestClient overload in tests generating errors while running `validate.sh` script. Issue: #280

dbemiller · 2018-11-05T21:02:55Z

Bad PR was #705. Reverted in #724. Good PR committed as #724

This CL introduces a mechanism to fetch currencies rates periodically from a remote source. Those rates are stored in `CurrencyConverter` struct which can be injected in PBS to get rates. This doesn't introduce any changes in PBS workflow just yet. It also address issues described in prebid#722 regarding httptestClient overload in tests generating errors while running `validate.sh` script. Issue: prebid#280

hhhjort mentioned this issue Oct 23, 2018

Removes the buggy currency code #723

Merged

benjaminch mentioned this issue Oct 23, 2018

Introduce currency converter mechanism #724

Merged

dbemiller closed this as completed Nov 5, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Currency tests failing sporadically #722

Currency tests failing sporadically #722

dbemiller commented Oct 23, 2018 •

edited

Loading

dbemiller commented Oct 23, 2018

dbemiller commented Oct 23, 2018

hhhjort commented Oct 23, 2018

dbemiller commented Oct 23, 2018 •

edited

Loading

benjaminch commented Oct 23, 2018 •

edited

Loading

dbemiller commented Oct 23, 2018

benjaminch commented Oct 23, 2018

benjaminch commented Oct 23, 2018

dbemiller commented Oct 23, 2018

benjaminch commented Oct 23, 2018

dbemiller commented Oct 23, 2018

hhhjort commented Oct 23, 2018

dbemiller commented Nov 5, 2018 •

edited

Loading

Currency tests failing sporadically #722

Currency tests failing sporadically #722

Comments

dbemiller commented Oct 23, 2018 • edited Loading

dbemiller commented Oct 23, 2018

dbemiller commented Oct 23, 2018

hhhjort commented Oct 23, 2018

dbemiller commented Oct 23, 2018 • edited Loading

benjaminch commented Oct 23, 2018 • edited Loading

dbemiller commented Oct 23, 2018

benjaminch commented Oct 23, 2018

benjaminch commented Oct 23, 2018

dbemiller commented Oct 23, 2018

benjaminch commented Oct 23, 2018

dbemiller commented Oct 23, 2018

hhhjort commented Oct 23, 2018

dbemiller commented Nov 5, 2018 • edited Loading

dbemiller commented Oct 23, 2018 •

edited

Loading

dbemiller commented Oct 23, 2018 •

edited

Loading

benjaminch commented Oct 23, 2018 •

edited

Loading

dbemiller commented Nov 5, 2018 •

edited

Loading