Libation icon indicating copy to clipboard operation
Libation copied to clipboard

Better error messages for these scenarios

Open rmcrackan opened this issue 3 years ago • 2 comments

Problem

These 2 bug reports keep coming to me in reddit PMs

  1. they don't have permission -- especially if a book expired from the Plus catalog between the time when they scanned and tried to download
  2. the rare user will start getting errors on all downloads. Libation won't work with audible for some people for about a day. It always comes back on its own in less than 2 days and doesn't seem to happen again. It doesn't seem to be users who hit the api a lot. I can find no pattern. Once they tell me it's every download, I know this is happening.

Solution

In the case of common misunderstandings, it's the system's fault for not being more clear.

  1. Libation should be able to detect license issues and let the user know that the most likely cause is returned book or audible removed it from plus. Ideally we'd also know it's a plus title but we don't currently track that
  2. The only one of these I can find logs for right now is #336 which was logged as a networking error -- I don't know if this is the same or not. Any time there's a batch of more than 3 books with 100% failures, we should suggest waiting a day and creating an issue ticket with log file if it doesn't resolve itself.

rmcrackan avatar Aug 11 '22 12:08 rmcrackan

Re 2, I suspect that inside the Audible app there is a built-in fallback to a secondary server when the primary is offline due to maintenance or an upgrade. The timing makes sense (being unreachable for ~1 day). Ideally we would debug the real audible app while the primary is down to find the secondary endpoint, but I haven't been able to do that yet.

Mbucari avatar Aug 11 '22 19:08 Mbucari

I assumed something like that must be the case. I originally suspected that they were punishing heavy users but there's a lot of reasons that doesn't add up. Unless we can catch it in the act and intercept the new traffic, all we can really do is inform the user.

rmcrackan avatar Aug 11 '22 19:08 rmcrackan

It's funny you closed this now, because I was thinking about this problem and I think I've discovered a pattern. In both cases, GetDownloadLicenseAsync fails with a "Content License denied ..." message. All license denials come with license denial reasons like this:

{
   "license_denial_reasons":[
      {
         "message":"...",
         "rejectionReason":"RequesterEligibility",
         "validationType":"Membership"
      },
      {
         "message":"...",
         "rejectionReason":"RequesterEligibility",
         "validationType":"Ownership"
      },
      {
         "message":"...",
         "rejectionReason":"RequesterEligibility",
         "validationType":"Client"
      },
      {
         "message":"...",
         "rejectionReason":"ContentEligibility",
         "validationType":"AYCL"
      }
   ]
}

I've looked through a lot of logs from old issues, and it seems like every time a license is denied because of reason 2 (random error that resolves itself in a few days), the "Client" validation type message is this:

{
   "message":"Since ClientId is null, skipping client rights validation.AAAClientId[ApolloEnv:AudibleApiExternalRouterService/EU/Prod], does not has access to asin[######].",
   "rejectionReason":"RequesterEligibility",
   "validationType":"Client"
}

and the "AYCL" validation type message is this:

{
   "message":"Customer [#############] has rights to asin [######] for AYCL",
   "rejectionReason":null,
   "validationType":"AYCL"
}

When the license is legitamately denied (reason 1), "Client" message never says "Since ClientId is null..." and the "AYCL" rejectionReason is never null.

If that is indeed the pattern, it's easily detectable and we can make more useful error messages.

Mbucari avatar Dec 14 '22 23:12 Mbucari

That would be very cool. I was thinking I'd have to subscribe to a 'plus' title, wait for it to expire so it's in my library in that state, then remember to query it again. And I just wasn't feeling up for it. So I closed this as a little bit of house cleaning. By all means, if you feel like it -- go for it

rmcrackan avatar Dec 15 '22 02:12 rmcrackan

OK, I did a deep dive and I'm feeling really good about this theory. I downloaded every attached log file for every one of Libation's past issues that contained "license_denial_reasons". Then I split them up by files that contained null and non-null values for the AYCL rejectionReason. No files had both null and non-null values. Finally, I went to each issue and tried to figure out if it was a legitimate case of license denial (reason 1), or a classic case of temporary denial (reason 2). Here are the results:

Issue Has null AYCL? Summary
Issue Link No Looks like titles are no longer in his audible library
Issue Link No title removed from plus catalog
Issue Link No issue unrelated to license denial
Issue Link No Seems like some kind of account-specific authentication error
Issue Link No issue unrelated to license denial
Issue Link No issue unrelated to license denial
Issue Link No One title that user no longer had rights to
Issue Link YES Classic case
Issue Link YES Classic case
Issue Link YES issue unrelated to license denial, but still had many consecutive null AYCL in a short time
Issue Link YES Classic case
Issue Link No User removed titles from Audible library, but not from Libation
Issue Link YES Classic case
Issue Link YES Classic case
Issue Link YES Classic case
Issue Link No issue unrelated to license denial, though titles removed from plus catalog
Issue Link No issue unrelated to license denial, though titles removed from plus catalog
Issue Link No issue unrelated to license denial, though titles removed from plus catalog
Issue Link No Lots of license denials, but those appear to be titles that were removed from plus
Issue Link No New AYCL rejection reason "GenericError"

Now I feel pretty confident that a null AYCL rejectionReason indicates a temporary denial of service error.

Mbucari avatar Dec 15 '22 06:12 Mbucari

Holy good golly -- that's some serious log diving

rmcrackan avatar Dec 15 '22 16:12 rmcrackan