Log Postgres test failures more verbosely, fix SubscriptionChange.IsEmpty.
SubscriptionChange.IsEmpty() would return false even if no actual database
operations are going to be performed. This is because we allow information we
_don't_ store in the database (Stripe source, Stripe email) to be specified in a
SubscriptionChange object, just so we can easily access them. Then we use the
Stripe API to store them in Stripe's databases, and turn them into data _we_
store in our database. Think of them as pre-processed values that are never
stored raw.
The problem is, we were treating these properties the same as the properties we
actually stored in the database, and (worse) were running database tests for
combinations of these properties, which was causing test failures because we
were trying to update no columns in the database. Whoops.
I removed these properties from the IsEmpty helper, and removed them from the
code that generates the SubscriptionChange permutations for testing. This allows
tests to pass, but also stays closer to what the system was designed to do.
In tracking down this bug, I discovered that the logging we had for errors when
running Postgres tests was inadequate, so I updated the logs when that failure
occurs while testing Postgres to help surface future failures faster.
9 "code.secondbit.org/uuid.hg"
13 subscriptionChangeStripeSubscription = 1 << iota
14 subscriptionChangePlan
15 subscriptionChangeStatus
16 subscriptionChangeCanceling
17 subscriptionChangeTrialStart
18 subscriptionChangeTrialEnd
19 subscriptionChangePeriodStart
20 subscriptionChangePeriodEnd
21 subscriptionChangeCanceledAt
22 subscriptionChangeFailedChargeAttempts
23 subscriptionChangeLastFailedCharge
24 subscriptionChangeLastNotified
28 if os.Getenv("PG_TEST_DB") != "" {
29 p, err := NewPostgres(os.Getenv("PG_TEST_DB"))
33 testSubscriptionStores = append(testSubscriptionStores, p)
37 var testSubscriptionStores = []SubscriptionStore{
41 func compareSubscriptions(sub1, sub2 Subscription) (bool, string, interface{}, interface{}) {
42 if !sub1.UserID.Equal(sub2.UserID) {
43 return false, "UserID", sub1.UserID, sub2.UserID
45 if sub1.StripeSubscription != sub2.StripeSubscription {
46 return false, "StripeSubscription", sub1.StripeSubscription, sub2.StripeSubscription
48 if sub1.Plan != sub2.Plan {
49 return false, "Plan", sub1.Plan, sub2.Plan
51 if sub1.Status != sub2.Status {
52 return false, "Status", sub1.Status, sub2.Status
54 if sub1.Canceling != sub2.Canceling {
55 return false, "Canceling", sub1.Canceling, sub2.Canceling
57 if !sub1.Created.Equal(sub2.Created) {
58 return false, "Created", sub1.Created, sub2.Created
60 if !sub1.TrialStart.Equal(sub2.TrialStart) {
61 return false, "TrialStart", sub1.TrialStart, sub2.TrialStart
63 if !sub1.TrialEnd.Equal(sub2.TrialEnd) {
64 return false, "TrialEnd", sub1.TrialEnd, sub2.TrialEnd
66 if !sub1.PeriodStart.Equal(sub2.PeriodStart) {
67 return false, "PeriodStart", sub1.PeriodStart, sub2.PeriodStart
69 if !sub1.PeriodEnd.Equal(sub2.PeriodEnd) {
70 return false, "PeriodEnd", sub1.PeriodEnd, sub2.PeriodEnd
72 if !sub1.CanceledAt.Equal(sub2.CanceledAt) {
73 return false, "CanceledAt", sub1.CanceledAt, sub2.CanceledAt
75 if sub1.FailedChargeAttempts != sub2.FailedChargeAttempts {
76 return false, "FailedChargeAttempts", sub1.FailedChargeAttempts, sub2.FailedChargeAttempts
78 if !sub1.LastFailedCharge.Equal(sub2.LastFailedCharge) {
79 return false, "LastFailedCharge", sub1.LastFailedCharge, sub2.LastFailedCharge
81 if !sub1.LastNotified.Equal(sub2.LastNotified) {
82 return false, "LastNotified", sub1.LastNotified, sub2.LastNotified
84 return true, "", nil, nil
87 func subscriptionMapContains(subscriptionMap map[string]Subscription, subscriptions ...Subscription) (bool, []Subscription) {
88 var missing []Subscription
89 for _, sub := range subscriptions {
90 if _, ok := subscriptionMap[sub.UserID.String()]; !ok {
91 missing = append(missing, sub)
100 func compareSubscriptionStats(stat1, stat2 SubscriptionStats) (bool, string, interface{}, interface{}) {
101 if stat1.Number != stat2.Number {
102 return false, "Number", stat1.Number, stat2.Number
104 if stat1.Canceling != stat2.Canceling {
105 return false, "Canceling", stat1.Canceling, stat2.Canceling
107 if stat1.Failing != stat2.Failing {
108 return false, "Failing", stat1.Failing, stat2.Failing
110 if len(stat1.Plans) != len(stat2.Plans) {
111 return false, "Plans", stat1.Plans, stat2.Plans
113 for key, count := range stat1.Plans {
114 count2, ok := stat2.Plans[key]
116 return false, "Plans", stat1.Plans, stat2.Plans
119 return false, "Plans", stat1.Plans, stat2.Plans
122 return true, "", nil, nil
125 func TestCreateSubscription(t *testing.T) {
126 for _, store := range testSubscriptionStores {
129 t.Fatalf("Error resetting %T: %+v\n", store, err)
131 customerID := uuid.NewID()
134 StripeSubscription: "stripeSubscription1",
135 Created: time.Now().Round(time.Millisecond),
136 TrialStart: time.Now().Round(time.Millisecond),
137 TrialEnd: time.Now().Round(time.Millisecond).Add(time.Hour * 24 * 31),
139 err = store.CreateSubscription(sub)
141 t.Errorf("Error creating subscription in %T: %+v\n", store, err)
143 retrieved, err := store.GetSubscriptions([]uuid.ID{sub.UserID})
145 t.Errorf("Error retrieving subscription from %T: %+v\n", store, err)
147 if _, returned := retrieved[sub.UserID.String()]; !returned {
148 t.Errorf("Error retrieving subscription from %T: %s wasn't in the results.", store, sub.UserID)
150 ok, field, expected, result := compareSubscriptions(sub, retrieved[sub.UserID.String()])
152 t.Errorf("Expected %s to be %v, got %v from %T\n", field, expected, result, store)
154 err = store.CreateSubscription(sub)
155 if err != ErrSubscriptionAlreadyExists {
156 t.Errorf("Unexpected error creating subscription in %T (wanted %+v): %+v\n", store, ErrSubscriptionAlreadyExists, err)
158 sub.UserID = uuid.NewID()
159 err = store.CreateSubscription(sub)
160 if err != ErrStripeSubscriptionAlreadyExists {
161 t.Errorf("Unexpected error creating subscription in %T (wanted %+v): %#+v\n", store, ErrStripeSubscriptionAlreadyExists, err)
163 sub.StripeSubscription = "stripeSubscription2"
164 err = store.CreateSubscription(sub)
166 t.Errorf("Error creating subscription in %T: %+v\n", store, err)
171 func TestUpdateSubscription(t *testing.T) {
172 variations := 1 << 12
174 UserID: uuid.NewID(),
175 StripeSubscription: "default",
176 Created: time.Now().Round(time.Millisecond).Add(time.Hour * -24 * -32),
177 TrialStart: time.Now().Round(time.Millisecond).Add(time.Hour * -24 * -32),
178 TrialEnd: time.Now().Round(time.Millisecond).Add(time.Hour * -24),
179 LastNotified: time.Now().Round(time.Millisecond).Add(time.Hour * -24),
181 sub2 := Subscription{
182 UserID: uuid.NewID(),
183 StripeSubscription: "stripeSubscription2",
184 Created: time.Now().Round(time.Millisecond),
185 TrialStart: time.Now().Round(time.Millisecond),
186 TrialEnd: time.Now().Round(time.Millisecond),
187 LastNotified: time.Now().Round(time.Millisecond),
190 for _, store := range testSubscriptionStores {
193 t.Fatalf("Error resetting %T: %+v\n", store, err)
195 err = store.CreateSubscription(sub)
197 t.Fatalf("Error saving subscription in %T: %s\n", store, err)
199 for i := 1; i < variations; i++ {
200 var stripeSubscription, plan, status string
202 var failedChargeAttempts int
203 var trialStart, trialEnd, periodStart, periodEnd, canceledAt, lastFailedCharge, lastNotified time.Time
205 change := SubscriptionChange{}
206 empty := change.IsEmpty()
208 t.Errorf("Expected empty to be %t, was %t\n", true, empty)
211 strI := strconv.Itoa(i)
213 if i&subscriptionChangeStripeSubscription != 0 {
214 stripeSubscription = "stripeSubscription-" + strI
215 change.StripeSubscription = &stripeSubscription
216 sub.StripeSubscription = stripeSubscription
219 if i&subscriptionChangePlan != 0 {
220 plan = "plan-" + strI
225 if i&subscriptionChangeStatus != 0 {
226 status = "status-" + strI
227 change.Status = &status
231 if i&subscriptionChangeCanceling != 0 {
233 change.Canceling = &canceling
234 sub.Canceling = canceling
237 if i&subscriptionChangeTrialStart != 0 {
238 trialStart = time.Now().Round(time.Millisecond).Add(time.Hour * time.Duration(i))
239 change.TrialStart = &trialStart
240 sub.TrialStart = trialStart
243 if i&subscriptionChangeTrialEnd != 0 {
244 trialEnd = time.Now().Round(time.Millisecond).Add(time.Hour * time.Duration(i))
245 change.TrialEnd = &trialEnd
246 sub.TrialEnd = trialEnd
249 if i&subscriptionChangePeriodStart != 0 {
250 periodStart = time.Now().Round(time.Millisecond).Add(time.Hour * time.Duration(i))
251 change.PeriodStart = &periodStart
252 sub.PeriodStart = periodStart
255 if i&subscriptionChangePeriodEnd != 0 {
256 periodEnd = time.Now().Round(time.Millisecond).Add(time.Hour * time.Duration(i))
257 change.PeriodEnd = &periodEnd
258 sub.PeriodEnd = periodEnd
261 if i&subscriptionChangeCanceledAt != 0 {
262 canceledAt = time.Now().Round(time.Millisecond).Add(time.Hour * time.Duration(i))
263 change.CanceledAt = &canceledAt
264 sub.CanceledAt = canceledAt
267 if i&subscriptionChangeFailedChargeAttempts != 0 {
268 failedChargeAttempts = i
269 change.FailedChargeAttempts = &failedChargeAttempts
270 sub.FailedChargeAttempts = failedChargeAttempts
273 if i&subscriptionChangeLastFailedCharge != 0 {
274 lastFailedCharge = time.Now().Round(time.Millisecond).Add(time.Hour * time.Duration(i))
275 change.LastFailedCharge = &lastFailedCharge
276 sub.LastFailedCharge = lastFailedCharge
279 if i&subscriptionChangeLastNotified != 0 {
280 lastNotified = time.Now().Round(time.Millisecond).Add(time.Hour * time.Duration(i))
281 change.LastNotified = &lastNotified
282 sub.LastNotified = lastNotified
285 empty = change.IsEmpty()
287 t.Errorf("Expected empty to be %t, was %t\n", false, empty)
290 result.ApplyChange(change)
291 match, field, expected, got := compareSubscriptions(sub, result)
293 t.Errorf("Expected field `%s` to be `%v`, got `%v`\n", field, expected, got)
295 err = store.UpdateSubscription(sub.UserID, change)
297 t.Logf("Change %d: %+v\n", i, change)
298 if p, ok := store.(Postgres); ok {
299 query := p.updateSubscriptionSQL(sub.UserID, change)
300 t.Log(query.String())
303 t.Errorf("Error updating subscription in %T: %s\n", store, err)
305 retrieved, err := store.GetSubscriptions([]uuid.ID{sub.UserID})
307 t.Errorf("Error getting subscription from %T: %s\n", store, err)
309 ok, missing := subscriptionMapContains(retrieved, sub)
311 t.Errorf("Expected to retrieve %s from %T, but missing was %+v\n", sub.UserID.String(), store, missing)
313 match, field, expected, got = compareSubscriptions(sub, retrieved[sub.UserID.String()])
315 t.Errorf("Expected field `%s` to be `%v`, got `%v` from %T\n", field, expected, got, store)
320 err = store.CreateSubscription(sub2)
322 t.Fatalf("Error saving subscription in %T: %+v\n", store, err)
324 change := SubscriptionChange{}
325 err = store.UpdateSubscription(sub.UserID, change)
326 if err != ErrSubscriptionChangeEmpty {
327 t.Errorf("Expected err to be %+v, but got %+v from %T\n", ErrSubscriptionChangeEmpty, err, store)
329 stripeSubscription := sub2.StripeSubscription
330 change.StripeSubscription = &stripeSubscription
331 err = store.UpdateSubscription(uuid.NewID(), change)
332 if err != ErrSubscriptionNotFound {
333 t.Errorf("Expected err to be %+v, but got %+v from %T\n", ErrSubscriptionNotFound, err, store)
335 err = store.UpdateSubscription(sub.UserID, change)
336 if err != ErrStripeSubscriptionAlreadyExists {
337 t.Errorf("Expected err to be %+v, but got %+v from %T\n", ErrStripeSubscriptionAlreadyExists, err, store)
342 func TestDeleteSubscription(t *testing.T) {
343 for _, store := range testSubscriptionStores {
346 t.Fatalf("Error resetting %T: %+v\n", store, err)
348 sub1 := Subscription{
349 UserID: uuid.NewID(),
350 StripeSubscription: "stripeSubscription1",
352 sub2 := Subscription{
353 UserID: uuid.NewID(),
354 StripeSubscription: "stripeSubscription2",
356 err = store.CreateSubscription(sub1)
358 t.Fatalf("Error creating %+v in %T: %+v\n", sub1, store, err)
360 err = store.CreateSubscription(sub2)
362 t.Fatalf("Error creating %+v in %T: %+v\n", sub2, store, err)
364 err = store.DeleteSubscription(sub1.UserID)
366 t.Fatalf("Error deleting %+v in %T: %+v\n", sub1, store, err)
368 retrieved, err := store.GetSubscriptions([]uuid.ID{sub1.UserID, sub2.UserID})
370 t.Errorf("Error retrieving subscriptions from %T: %+v\n", store, err)
372 ok, missing := subscriptionMapContains(retrieved, sub1)
374 t.Errorf("Expected not to retrieve %s from %T, but missing was %+v\n", sub1.UserID.String(), store, missing)
376 ok, missing = subscriptionMapContains(retrieved, sub2)
378 t.Errorf("Expected to retrieve %s from %T, but missing was %+v\n", sub2.UserID.String(), store, missing)
380 err = store.DeleteSubscription(sub1.UserID)
381 if err != ErrSubscriptionNotFound {
382 t.Errorf("Expected err to be %+v, but got %+v from %T\n", ErrSubscriptionNotFound, err, store)
387 func TestGetSubscriptions(t *testing.T) {
388 for _, store := range testSubscriptionStores {
391 t.Fatalf("Error resetting %T: %+v\n", store, err)
393 sub1 := Subscription{
394 UserID: uuid.NewID(),
395 StripeSubscription: "stripeSubscription1",
397 Created: time.Now().Round(time.Millisecond),
398 TrialStart: time.Now().Round(time.Millisecond),
399 TrialEnd: time.Now().Round(time.Millisecond).Add(time.Hour * 24 * 32),
401 sub2 := Subscription{
402 UserID: uuid.NewID(),
403 StripeSubscription: "stripeSubscription2",
405 Created: time.Now().Round(time.Millisecond).Add(time.Hour * -720),
406 TrialStart: time.Now().Round(time.Millisecond).Add(time.Hour * -720),
407 TrialEnd: time.Now().Round(time.Millisecond),
409 sub3 := Subscription{
410 UserID: uuid.NewID(),
411 StripeSubscription: "stripeSubscription3",
413 Created: time.Now().Round(time.Millisecond).Add(time.Hour * -1440),
414 TrialStart: time.Now().Round(time.Millisecond).Add(time.Hour * -1440),
415 TrialEnd: time.Now().Round(time.Millisecond).Add(time.Hour * -720),
416 PeriodStart: time.Now().Round(time.Millisecond).Add(time.Hour * -720),
417 PeriodEnd: time.Now().Round(time.Millisecond),
420 err = store.CreateSubscription(sub1)
422 t.Fatalf("Error creating %+v in %T: %+v\n", sub1, store, err)
424 err = store.CreateSubscription(sub2)
426 t.Fatalf("Error creating %+v in %T: %+v\n", sub1, store, err)
428 err = store.CreateSubscription(sub3)
430 t.Fatalf("Error creating %+v in %T: %+v\n", sub1, store, err)
432 retrieved, err := store.GetSubscriptions([]uuid.ID{})
433 if err != ErrNoSubscriptionID {
434 t.Errorf("Error retrieving no subscriptions from %T. Expected %+v, got %+v\n", store, ErrNoSubscriptionID, err)
436 retrieved, err = store.GetSubscriptions([]uuid.ID{sub1.UserID})
438 t.Errorf("Error retrieving %s from %T: %+v\n", sub1.UserID, store, err)
440 ok, missing := subscriptionMapContains(retrieved, sub1)
442 t.Logf("Results: %+v\n", retrieved)
443 t.Errorf("Expected %+v to be in the results, was not for %T.\n", missing, store)
445 retrieved, err = store.GetSubscriptions([]uuid.ID{sub1.UserID, sub2.UserID})
447 t.Errorf("Error retrieving %s and %s from %T: %+v\n", sub1.UserID, sub2.UserID, store, err)
449 ok, missing = subscriptionMapContains(retrieved, sub1, sub2)
451 t.Logf("Results: %+v\n", retrieved)
452 t.Errorf("Expected %+v to be in the results, was not for %T.\n", missing, store)
454 retrieved, err = store.GetSubscriptions([]uuid.ID{sub1.UserID, sub3.UserID})
456 t.Errorf("Error retrieving %s and %s from %T: %+v\n", sub1.UserID, sub3.UserID, store, err)
458 ok, missing = subscriptionMapContains(retrieved, sub1, sub3)
460 t.Logf("Results: %+v\n", retrieved)
461 t.Errorf("Expected %+v to be in the results, was not for %T.\n", missing, store)
463 retrieved, err = store.GetSubscriptions([]uuid.ID{sub1.UserID, sub2.UserID, sub3.UserID})
465 t.Errorf("Error retrieving %s, %s, and %s from %T: %+v\n", sub1.UserID, sub2.UserID, sub3.UserID, store, err)
467 ok, missing = subscriptionMapContains(retrieved, sub1, sub2, sub3)
469 t.Logf("Results: %+v\n", retrieved)
470 t.Errorf("Expected %+v to be in the results, was not for %T.\n", missing, store)
472 retrieved, err = store.GetSubscriptions([]uuid.ID{sub2.UserID})
474 t.Errorf("Error retrieving %s from %T: %+v\n", sub2.UserID, store, err)
476 ok, missing = subscriptionMapContains(retrieved, sub2)
478 t.Logf("Results: %+v\n", retrieved)
479 t.Errorf("Expected %+v to be in the results, was not for %T.\n", missing, store)
481 retrieved, err = store.GetSubscriptions([]uuid.ID{sub2.UserID, sub3.UserID})
483 t.Errorf("Error retrieving %s and %s from %T: %+v\n", sub2.UserID, sub3.UserID, store, err)
485 ok, missing = subscriptionMapContains(retrieved, sub2, sub3)
487 t.Logf("Results: %+v\n", retrieved)
488 t.Errorf("Expected %+v to be in the results, was not for %T.\n", missing, store)
490 retrieved, err = store.GetSubscriptions([]uuid.ID{sub3.UserID})
492 t.Errorf("Error retrieving %s from %T: %+v\n", sub3.UserID, store, err)
494 ok, missing = subscriptionMapContains(retrieved, sub3)
496 t.Logf("Results: %+v\n", retrieved)
497 t.Errorf("Expected %+v to be in the results, was not for %T.\n", missing, store)
499 retrieved, err = store.GetSubscriptions([]uuid.ID{uuid.NewID()})
501 t.Errorf("Error retrieving non-existent ID from %T: %+v\n", store, err)
503 if len(retrieved) != 0 {
504 t.Errorf("Expected no results, %T returned %+v\n", store, retrieved)
506 retrieved, err = store.GetSubscriptions([]uuid.ID{sub1.UserID, sub2.UserID, uuid.NewID(), sub3.UserID})
508 t.Errorf("Error retrieving non-existent ID from %T: %+v\n", store, err)
510 if len(retrieved) != 3 {
511 t.Errorf("Expected 3 results, %T returned %+v\n", store, retrieved)
513 ok, missing = subscriptionMapContains(retrieved, sub1, sub2, sub3)
515 t.Logf("Results: %+v\n", retrieved)
516 t.Errorf("Expected %+v to be in the results, was not for %T.\n", missing, store)
521 func TestGetSubscriptionStats(t *testing.T) {
522 for _, store := range testSubscriptionStores {
525 t.Fatalf("Error resetting %T: %+v\n", store, err)
527 sub1 := Subscription{
528 UserID: uuid.NewID(),
529 StripeSubscription: "stripeSubscription1",
533 sub2 := Subscription{
534 UserID: uuid.NewID(),
535 StripeSubscription: "stripeSubscription2",
539 err = store.CreateSubscription(sub1)
541 t.Fatalf("Error creating %+v in %T: %+v\n", sub1, store, err)
543 stats, err := store.GetSubscriptionStats()
545 t.Errorf("Error getting stats from %T: %+v\n", store, err)
547 ok, field, expected, results := compareSubscriptionStats(SubscriptionStats{
551 Plans: map[string]int64{
556 t.Errorf("Expected %s to be %+v, got %+v from %T\n", field, expected, results, store)
558 err = store.CreateSubscription(sub2)
560 t.Fatalf("Error creating %+v in %T: %+v\n", sub2, store, err)
562 stats, err = store.GetSubscriptionStats()
564 t.Errorf("Error getting status from %T: %+v\n", store, err)
566 ok, field, expected, results = compareSubscriptionStats(SubscriptionStats{
570 Plans: map[string]int64{
576 t.Errorf("Expected %s to be %+v, got %+v from %T\n", field, expected, results, store)
578 err = store.DeleteSubscription(sub1.UserID)
580 t.Errorf("Error deleting subscription from %T: %+v\n", store, err)
582 stats, err = store.GetSubscriptionStats()
584 t.Errorf("Error getting status from %T: %+v\n", store, err)
586 ok, field, expected, results = compareSubscriptionStats(SubscriptionStats{
590 Plans: map[string]int64{
595 t.Errorf("Expected %s to be %+v, got %+v from %T\n", field, expected, results, store)