[match][spaceship] large amount of bundle_ids in `Matchfile` causes Connect API to fail and return HTML about fastlane

[ff-ahumberston]

Also receive this error on occasion, with no obvious consistency between the two errors.

Looking for related GitHub issues on fastlane/fastlane...

bundler: failed to load command: fastlane (/Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/bin/fastlane)
Traceback (most recent call last):
        47: from /Users/admin/.rbenv/versions/2.6.5/bin/bundle:23:in `<main>'
        46: from /Users/admin/.rbenv/versions/2.6.5/bin/bundle:23:in `load'
        45: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/exe/bundle:37:in `<top (required)>'
        44: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/friendly_errors.rb:128:in `with_friendly_errors'
        43: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/exe/bundle:49:in `block in <top (required)>'
        42: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/cli.rb:25:in `start'
        41: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'
        40: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/cli.rb:31:in `dispatch'
        39: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'
        38: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'
        37: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
        36: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/cli.rb:475:in `exec'
        35: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/cli/exec.rb:28:in `run'
        34: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/cli/exec.rb:63:in `kernel_load'
        33: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/bundler-2.2.24/lib/bundler/cli/exec.rb:63:in `load'
        32: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/bin/fastlane:23:in `<top (required)>'
        31: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/bin/fastlane:23:in `load'
        30: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/bin/fastlane:23:in `<top (required)>'
        29: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/fastlane/lib/fastlane/cli_tools_distributor.rb:115:in `take_off'
        28: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/match/lib/match/commands_generator.rb:26:in `start'
        27: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/match/lib/match/commands_generator.rb:186:in `run'
        26: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/commander-4.6.0/lib/commander/delegates.rb:18:in `run!'
        25: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/fastlane_core/lib/fastlane_core/ui/fastlane_runner.rb:124:in `run!'
        24: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/commander-4.6.0/lib/commander/runner.rb:444:in `run_active_command'
        23: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/commander-4.6.0/lib/commander/command.rb:157:in `run'
        22: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/commander-4.6.0/lib/commander/command.rb:187:in `call'
        21: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/match/lib/match/commands_generator.rb:69:in `block (3 levels) in run'
        20: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/match/lib/match/runner.rb:79:in `run'
        19: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/match/lib/match/runner.rb:79:in `each'
        18: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/match/lib/match/runner.rb:80:in `block in run'
        17: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/match/lib/match/portal_cache.rb:69:in `bundle_ids'
        16: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/match/lib/match/portal_fetcher.rb:64:in `bundle_ids'
        15: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/connect_api/models/bundle_id.rb:44:in `all'
        14: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/connect_api/response.rb:57:in `all_pages'
        13: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/connect_api/response.rb:44:in `next_pages'
        12: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/connect_api/response.rb:44:in `loop'
        11: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/connect_api/response.rb:45:in `block in next_pages'
        10: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/connect_api/response.rb:31:in `next_page'
         9: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/connect_api/provisioning/client.rb:29:in `get'
         8: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/connect_api/provisioning/client.rb:54:in `proxy_get'
         7: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/client.rb:772:in `request'
         6: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/client.rb:928:in `send_request'
         5: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/client.rb:687:in `with_retry'
         4: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/client.rb:932:in `block in send_request'
         3: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/connect_api/api_client.rb:252:in `handle_error'
         2: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/fastlane-2.219.0/spaceship/lib/spaceship/connect_api/api_client.rb:338:in `format_errors'
         1: from /Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/json-2.7.1/lib/json/common.rb:219:in `parse'
/Users/admin/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/json-2.7.1/lib/json/common.rb:219:in `parse': [!] unexpected token at '<!DOCTYPE html> (JSON::ParserError)
<html xmlns="https://www.w3.org/1999/xhtml" xml:lang="en" lang="en">
<head>

<meta http-equiv="content-type" content="text/html; charset=utf-8" />
<meta name="Author" content="Apple Inc." />
<meta name="viewport" content="width=device-width, initial-scale=1, viewport-fit=cover" />
<link rel="shortcut icon" href="/favicon.ico?17182335271" />
<link rel="icon" href="/favicon.ico?17182335271" />
<link rel="mask-icon" href="/apple-logo.svg?17182335271" color="#333333">

<link rel="stylesheet" href="/pagenotfound/styles/page-not-found.min.css?03182354271" type="text/css">
<link rel="stylesheet" href="/assets/styles/dark-mode.css?23182355271" type="text/css" media="(prefers-color-scheme: dark)" data-color-scheme="dark" />

<snipped> 

        <script src="/pagenotfound/scripts/page-not-found.js"></script>

</body>
</html>

[ff-ahumberston]

Looks to be related to the JSON parser receiving an unexpected HTML response.

Could be a repeat occurrence of the issue experienced in #15631

[ff-ahumberston]

After a fair amount of investigation, it was determined that the Matchfile contained too many entries and was the contributing factor that led to the resulting 404 error.

In the interim, removing older entries from the Matchfile has allowed match to process successfully.

[lacostej]

It is possible that the API has a maximum number of bundle ids to query that we are unaware of.
I haven't found anything on https://developer.apple.com/documentation/appstoreconnectapi/list_bundle_ids

The failure seems to be a 403 error, as we are in spaceship/lib/spaceship/connect_api/api_client.rb:252
The HTML page contains some reference to a possible page not found on Apple servers. So yes, maybe something failed internally.

You could enable debugging DEBUG=Y bundle exec fastlane match adhoc to see if we have more interesting information in the logs. In particular we could see the exact request that fails and start playing with it by reducing the number of bundle ids until we find a number that works.

We can definitely harden the APIClient.handle_error to handle the cases where HTML is returned to extract more relevant information.

[lacostej]

Reopening this one in favor of #21824

[ff-ahumberston]

Running the requested command (DEBUG=Y bundle exec fastlane match adhoc) results in the same error as previously posted, with no additional debug info.

[ff-ahumberston]

Having carried out some further tests today, the bundle ID limit within Matchfile looks to be 193. Over this and we receive the aforementioned error.

Also noticed that the length of the 'POST bundleIds: {"urlEncodedQueryParams":"' string was 5193 characters in length.

Unsure if the limit is the Matchfile size or the POST string length.

[lacostej]

Running the requested command (DEBUG=Y bundle exec fastlane match adhoc) results in the same error as previously posted, with no additional debug info.

Spaceship should create log files, and we are particularly interested in the last conversation. You might be able to find the content of the last query and its response in one of the log files.

[lacostej]

Another question: how many profiles do you have in your portal? You should be able to find the information by starting the fastlane spaceship console, login and enter ConnectAPI::BundleId.all.count

[lacostej]

I've tried reproducing this with my portal but we have ~110 in our portal.

I did create a query with a very large amount of bundle ids, by repeating the same bundle ids multiple time, and with a 64k string, it didn't fail. So I suspect something else is going on. Maybe one of the bundle ids you removed is special and causing issues?

[ff-ahumberston]

ConnectAPI::BundleId.all.count

Executing this command gives 477

[ff-ahumberston]

I've tried reproducing this with my portal but we have ~110 in our portal.

I did create a query with a very large amount of bundle ids, by repeating the same bundle ids multiple time, and with a 64k string, it didn't fail. So I suspect something else is going on. Maybe one of the bundle ids you removed is special and causing issues?

I just tried re-adding the bundleids that I stripped from Matchfile and excluding the others, the provisioning profiles were added successfully. It does not look to be a problematic bundleid.

[lacostej]

@ff-ahumberston I prepared a branch to handle this case a bit better. Right now, it should still fail, but provide a bit more information.

https://github.com/lacostej/fastlane/tree/fix/large_amount_bundleids

Are you able to try it out?

Also when running the command, can you try to run it with a VERBOSE environment variable?

$ VERBOSE=y bundle exec fastlane ...
[✔] 🚀 
Username: [email protected]
Logging into to App Store Connect ([email protected])...
[...]

See if you are able to look into the requests&responses to see what is really happening? I am particularly interested in the URLs that are requested in the pagination of the bundle_ids.

On my side I see things like this:

INFO  [17:20:28]: >> POST bundleIds: {"urlEncodedQueryParams":"","teamId":"xxxxx"} 
DEBUG [17:20:29]: << POST bundleIds: 200 {"data"=>[{"type"=>"bundleIds", "id"=>"yyyy", "attributes"=>{"identifier"=>"com.a.b", "dateModified"=>"2014-04-09T09:47:11.000+00:00", "entitlementGroupName"=>nil, "bundleType"=>"bundle", "platform"=>"IOS", "wildcard"=>false, "dateCreated"=>"2014-04-09T09:47:11.000+00:00", "bundleIdCapabilitiesSettingOption"=>nil, "seedId"=>"xxxx", "name"=>"Xcode iOS App ID com a b", "platformName"=>"iOS", "deploymentDataNotice"=>nil, "responseId"=>"c9de6eb3-9234-44b4-a806-af8681dde8a1"}, "relationships"=>{"bundleIdCapabilities"=>{"meta"=>{"paging"=>{"total"=>0, "limit"=>2147483647}}, "links"=>{"self"=>"https://developer.apple.com:443/services-account/v1/bundleIds/zzzz/relationships/bundleIdCapabilities", "related"=>"https://developer.apple.com:443/services-account/v1/bundleIds/zzzz/bundleIdCapabilities"}}, "profiles"=>{"meta"=>{"paging"=>{"total"=>0, "limit"=>2147483647}},

[ff-ahumberston]

@lacostej

Apologies for the delay in response, trying your branch does not look to give any additional debug output. I can run the verbose output, but I would rather not post it's content in the thread.

I could email to you if that would help.

[lacostej]

@ff-ahumberston feel free to mail the output. My email is in my github profile. Thanks!

[Dmitry-Pliushchai]

We have the similar issue but AppStoreConnect returns 403 error if there are more than 18 bundle ids in matchfile