setAttributes - some attributes randomly being ignored...

[alexstanbury]

I'm having a real head scratching issue with the setAttributes functionality, where randomly some attributes seem to be ignored.

They are all set to strings before being passed into setAttributes and are also stripped of any special characters.

It seems to be completely random, no consistency as to what causes an attribute to be ignored, which is leading me to believe there may be some kind of race condition somewhere, although having looked through the code I can't see anything obvious.

This may be a core iOS SDK issue and I'll post over there too.

As my logs below show, there are 9 attributes passed in, but only 4 get used:

2023-09-08 12:22:47.439156+0100 App[1670:452821] [attribution] DEBUG: ℹ️ setting values for attributes: ["accessId", "iapName", "currencyCode", "interval", "teamId", "tmId", "teamName", "userId", "cost"]
2023-09-08 12:22:47.439710+0100 App[1670:452821] [attribution] DEBUG: ℹ️ Attribute set locally: [SubscriberAttribute] key: accessId value: 2 setTime: 2023-09-08 11:22:47 +0000. It will be synced to the backend when the app backgrounds/foregrounds or when a purchase is made.
2023-09-08 12:22:47.441869+0100 App[1670:452821] [attribution] DEBUG: ℹ️ Attribute set locally: [SubscriberAttribute] key: iapName value: MY_IAP_NAME_HERE setTime: 2023-09-08 11:22:47 +0000. It will be synced to the backend when the app backgrounds/foregrounds or when a purchase is made.
2023-09-08 12:22:47.443554+0100 App[1670:452821] [attribution] DEBUG: ℹ️ Attribute set locally: [SubscriberAttribute] key: interval value: month setTime: 2023-09-08 11:22:47 +0000. It will be synced to the backend when the app backgrounds/foregrounds or when a purchase is made.
2023-09-08 12:22:47.445877+0100 App[1670:452821] [attribution] DEBUG: ℹ️ Attribute set locally: [SubscriberAttribute] key: cost value: 5 setTime: 2023-09-08 11:22:47 +0000. It will be synced to the backend when the app backgrounds/foregrounds or when a purchase is made.
⚡️  TO JS undefined
2023-09-08 12:22:47.447725+0100 App[1670:452821] [offering] DEBUG: ℹ️ Skipping products request for these products because they were already cached: ["MY_IAP_NAME_HERE"]
2023-09-08 12:22:47.448534+0100 App[1670:452496] [purchases] INFO: 💰 Purchasing Product 'MY_IAP_NAME_HERE'
2023-09-08 12:22:47.449512+0100 App[1670:452496] [purchases] DEBUG: ℹ️ Adding payment for product 'MY_IAP_NAME_HERE'. 0 transactions already in the queue.
2023-09-08 12:22:47.451671+0100 App[1670:452821] [purchases] DEBUG: ℹ️ StoreKit1Wrapper (0x0000000283cfd020) updatedTransaction: MY_IAP_NAME_HERE 0
2023-09-08 12:22:47.458134+0100 App[1670:452821] [purchases] VERBOSE: The SKPaymentTransaction has a nil value for transaction date - this is a bug in StoreKit.
Unix Epoch will be used instead for the transaction within the app.
Transactions in the backend and in webhooks are unaffected and will have the correct timestamps.
Transaction state: SKPaymentTransactionState(rawValue: 0)
2023-09-08 12:22:47.458191+0100 App[1670:452821] [purchases] VERBOSE: The SKPaymentTransaction has a nil value for transaction identifier - this is a bug in StoreKit.
Transactions in the backend and in webhooks are unaffected and will have the correct identifier.
2023-09-08 12:23:03.238008+0100 App[1670:452883] [tcp] tcp_input [C1.1.1:3] flags=[R] seq=141240056, ack=0, win=0 state=LAST_ACK rcv_nxt=141240057, snd_una=757303259
2023-09-08 12:23:03.239182+0100 App[1670:452883] [tcp] tcp_input [C1.1.1:3] flags=[R] seq=141240056, ack=0, win=0 state=LAST_ACK rcv_nxt=141240057, snd_una=757303259
2023-09-08 12:23:03.240012+0100 App[1670:452883] [tcp] tcp_input [C1.1.1:3] flags=[R] seq=141240057, ack=0, win=0 state=LAST_ACK rcv_nxt=141240057, snd_una=757303259
2023-09-08 12:23:03.240854+0100 App[1670:452883] [tcp] tcp_input [C1.1.1:3] flags=[R] seq=141240057, ack=0, win=0 state=CLOSED rcv_nxt=141240057, snd_una=757303259

After backgrounding and then foregrounding the app, these are the logs:

2023-09-08 12:26:29.392922+0100 App[1670:453927] [attribution] INFO: ℹ️ Marking attributes as synced for App User ID: $RCAnonymousID:5dc4892b7dbd48dabb6a1b393c86941b:
 attributes: ["cost": [SubscriberAttribute] key: cost value: 5 setTime: 2023-09-08 11:22:47 +0000, "interval": [SubscriberAttribute] key: interval value: month setTime: 2023-09-08 11:22:47 +0000, "accessId": [SubscriberAttribute] key: accessId value: 2 setTime: 2023-09-08 11:22:47 +0000, "iapName": [SubscriberAttribute] key: iapName value: MY_IAP_NAME_HERE setTime: 2023-09-08 11:22:47 +0000]
2023-09-08 12:26:29.397407+0100 App[1670:453927] [attribution] DEBUG: ℹ️ Found 4 unsynced attributes for App User ID: $RCAnonymousID:5dc4892b7dbd48dabb6a1b393c86941b
2023-09-08 12:26:29.397847+0100 App[1670:453927] [attribution] DEBUG: ℹ️ Unsynced attributes: ["interval": [SubscriberAttribute] key: interval value: month setTime: 2023-09-08 11:22:47 +0000, "accessId": [SubscriberAttribute] key: accessId value: 2 setTime: 2023-09-08 11:22:47 +0000, "cost": [SubscriberAttribute] key: cost value: 5 setTime: 2023-09-08 11:22:47 +0000, "iapName": [SubscriberAttribute] key: iapName value: MY_IAP_NAME_HERE setTime: 2023-09-08 11:22:47 +0000]
2023-09-08 12:26:29.402380+0100 App[1670:453927] [attribution] DEBUG: 😻 Subscriber attributes synced successfully for App User ID: $RCAnonymousID:5dc4892b7dbd48dabb6a1b393c86941b
2023-09-08 12:26:29.402594+0100 App[1670:453927] [network] DEBUG: ℹ️ PostSubscriberAttributesOperation: Finished
2023-09-08 12:26:29.403023+0100 App[1670:453927] [network] DEBUG: ℹ️ Serial request done: POST /v1/subscribers/$RCAnonymousID%3A5dc4892b7dbd48dabb6a1b393c86941b/attributes, 0 requests left in the queue

I also noticed the typing of this function seems to be incorrect, it does not appear to return a promise.

[alexstanbury]

Further to this, I saw https://github.com/RevenueCat/purchases-ios/issues/499 and tried uninstalling the app. To my surprise, it worked as expected after reinstalling and testing. I had run into the linked issue where I was trying to use numbers in the data originally, but weirdly some of the attributes being ignored were never set to numbers.

Unfortunately, on the second run of the app (without reinstalling) the attributes are being ignored again, only this time it only kept 3 of them...

2023-09-08 12:55:23.367682+0100 App[1713:465539] [attribution] DEBUG: ℹ️ setting values for attributes: ["cost", "tmId", "accessId", "userId", "interval", "iapName", "teamId", "currencyCode", "teamName"]
2023-09-08 12:55:23.368099+0100 App[1713:465539] [attribution] DEBUG: ℹ️ Attribute set locally: [SubscriberAttribute] key: cost value: 120 setTime: 2023-09-08 11:55:23 +0000. It will be synced to the backend when the app backgrounds/foregrounds or when a purchase is made.
2023-09-08 12:55:23.370107+0100 App[1713:465539] [attribution] DEBUG: ℹ️ Attribute set locally: [SubscriberAttribute] key: interval value: year setTime: 2023-09-08 11:55:23 +0000. It will be synced to the backend when the app backgrounds/foregrounds or when a purchase is made.
2023-09-08 12:55:23.372435+0100 App[1713:465539] [attribution] DEBUG: ℹ️ Attribute set locally: [SubscriberAttribute] key: iapName value: MY_IAP_NAME_HERE setTime: 2023-09-08 11:55:23 +0000. It will be synced to the backend when the app backgrounds/foregrounds or when a purchase is made.
⚡️  TO JS undefined
2023-09-08 12:55:23.376695+0100 App[1713:465539] [offering] DEBUG: ℹ️ Skipping products request for these products because they were already cached:```

[alexstanbury]

I've dug into the swift code, and it looks like there is some issue with caching, I'm not going to go any further but this is where it falls down:

func storeAttributeLocallyIfNeeded(key: String, value: String?, appUserID: String) {
        let currentValue = currentValueForAttribute(key: key, appUserID: appUserID)
        print("currentValue", currentValue as Any);
        print("test", currentValue != (value ?? ""));
        if currentValue == nil || currentValue != (value ?? "") {
            print("do i get here?", currentValue as Any);
            storeAttributeLocally(key: key, value: value ?? "", appUserID: appUserID)
        }
    }

The test prints false, currentValueForAttribute seems to rely on some kind of cache, so it looks like something isn't being cleaned up properly after the attributes have successfully synced.

[tonidero]

Hi @alexstanbury, just a theory but is it possible the property didn't change value from the original value set in the cache? If so, we would only update the value if it has changed. Also, could you confirm you get the values in the RevenueCat dashboard for your user?

I also noticed the typing of this function seems to be incorrect, it does not appear to return a promise.

Could you add more details about this? The current setAttributes function is returning a Promise<void>: https://github.com/RevenueCat/purchases-capacitor/blob/6.0.0-beta.2/src/definitions.ts#L453

[alexstanbury]

You're right, it looks as though that is indeed the problem with the current situation - I think/hope the sequence of events that caused the problem is as follows:

Used setAttributes but with some of the attribute values not cast as strings (they were number). All of the attributes were added to the cache before any validation or remote syncing took place. Attributes were processed in sequence, when the first attribute that wasn't a string was encountered, the operation failed. The attributes that were placed after the problem attribute(s) in the sequence never got synced but remained in the cache. I Checked UI and API and there were attributes missing. These attributes remained in the cache and they don't change, meaning subsequent attempts to add them (even after casting to string) constantly failed because they were in the cache. Uninstalling app cleared the cache, meaning after reinstall they all got submitted as expected. Further to this, only attributes that change get submitted, as designed.

I think this issue could have been avoided by the attributes being parsed immediately when the call to setAttributes is made and failing early with a thrown error if they are not in the right format, before any caching takes place.

Regarding the promise, I am using a pretty dated setup, AngularJS with no Typescript, so I have to use the following syntax:

window.Capacitor.Plugins.Purchases.setAttributes({attributes:{test:'hello'}});

If I call it as a promise like:

window.Capacitor.Plugins.Purchases.setAttributes({attributes:{test:'hello'}}).then(function () {console.log("promise resolved")})

I get the error:

TypeError: window.Capacitor.Plugins.Purchases.setAttributes({test:'hello'}).then is not a function

However, I can call:

window.Capacitor.Plugins.Purchases.purchaseStoreProduct({ product: MY_PRODUCT_HERE }).then(function (purchase) {
                //stuff here
              }).catch(function (error) {
                //stuff here
              }).finally(function () {
                //stuff here
              })

And have no problems.

[tonidero]

I think this issue could have been avoided by the attributes being parsed immediately when the call to setAttributes is made and failing early with a thrown error if they are not in the right format, before any caching takes place.

It's tricky to perform this type of runtime type checking in a capacitor plugin since the plugin jumps directly to the Android/iOS counterparts so we can't perform the type check in typescript/javascript. But we will study our options for this.

TypeError: window.Capacitor.Plugins.Purchases.setAttributes({test:'hello'}).then is not a function

That's interesting... Looking at the generated javascript, I'm not sure why it wouldn't recognize this as a promise but it would for purchaseStoreProduct. One thing you could try is changing your code from:

window.Capacitor.Plugins.Purchases.setAttributes({attributes:{test:'hello'}}).then(function () {console.log("promise resolved")})

to

window.Capacitor.Plugins.Purchases.setAttributes({'test':'hello'}).then(function () {console.log("promise resolved")})

Though I'm not sure that's the cause of this issue...

[riderx]

@tonidero i can help you if you need for this, there is a way to make the TS/JS code of the plugin less dumb :) There no doc, but some good exemple like: https://github.com/transistorsoft/capacitor-background-geolocation/blob/master/src/index.ts

[tonidero]

Hey @riderx, thanks for that! After taking a look, seems like that solution could indeed help us adding some runtime checks for the types. However, it would also mean we need to handle calling the native methods manually ourselves. We will consider it though, since I don't think we have many options. Thanks again!

[aboedo]

@riderx thanks for the suggestion! 🙌

I'd like to figure out the exact source of the issue before taking action.

We have a suspicion that it might be related to Objective-C's dynamic typing for the dictionary of attributes that gets passed in to setAttributes: it might just be getting sent as the wrong type, and not caught in the intermediate layer.

We're going to try to reproduce based on that theory and add more info once we've dug in

[tonidero]

Hi @alexstanbury, after testing what happens when passing the wrong types when using Javascript, it seems that we currently set the value to an empty string, as indicated here: https://github.com/RevenueCat/purchases-hybrid-common/blob/main/ios/PurchasesHybridCommon/PurchasesHybridCommon/CommonFunctionality.swift#L448. I've also tested it and, after setting it a value with the wrong type (which gets set as an empty string in the cache), I can set a string value and the value is updated correctly according to my tests.

Does that match what you were experiencing?

[tonidero]

I'm going to close this since it's been inactive but feel free to reopen!