it always raises ** (ExAws.Error) ExAws Request Error! when i attempt to migrate

[vshev4enko]

When i attempt to create schema_migrations table by following command
mix ecto.migrate -r RepoDynamo -n 0
it always raises

** (ExAws.Error) ExAws Request Error!

{:error, {"ResourceNotFoundException", "Requested resource not found"}}

can i fix it somehow?

[darrenklein]

Thanks for reporting this issue. I just tested it myself, but it ran fine, I could not replicate the issue. I added configuration to an app to refer to a named schema migration table, "test_schema_migrations", then ran

mix ecto.migrate -r MyApp.Repo -n 0

which resulted in

12:39:57.477 [debug] ExAws: Request URL: "http://localhost:8000/" HEADERS: [{"Authorization", "AWS4-HMAC-SHA256 Credential=abcd/20200707/us-east-1/dynamodb/aws4_request,SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date;x-amz-target,Signature=4ebac17435b7854aeb454fa7e3c3f45bddfbfdc51800e3bad40832cfa0a09ae7"}, {"host", "localhost:8000"}, {"x-amz-date", "20200707T163957Z"}, {"x-amz-content-sha256", ""}, {"x-amz-target", "DynamoDB_20120810.ListTables"}, {"content-type", "application/x-amz-json-1.0"}] BODY: "{}" ATTEMPT: 1

12:39:57.516 [debug] ExAws: Request URL: "http://localhost:8000/" HEADERS: [{"Authorization", "AWS4-HMAC-SHA256 Credential=abcd/20200707/us-east-1/dynamodb/aws4_request,SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date;x-amz-target,Signature=8003b8c0e2539573e920b354a36cc43e423f0fbd6c7a55c6ec9418c27d2cea16"}, {"host", "localhost:8000"}, {"x-amz-date", "20200707T163957Z"}, {"x-amz-content-sha256", ""}, {"x-amz-target", "DynamoDB_20120810.CreateTable"}, {"content-type", "application/x-amz-json-1.0"}] BODY: "{\"AttributeDefinitions\":[{\"AttributeName\":\"version\",\"AttributeType\":\"N\"}],\"BillingMode\":\"PROVISIONED\",\"KeySchema\":[{\"AttributeName\":\"version\",\"KeyType\":\"HASH\"}],\"ProvisionedThroughput\":{\"ReadCapacityUnits\":1,\"WriteCapacityUnits\":1},\"TableName\":\"test_schema_migrations\"}" ATTEMPT: 1

12:39:57.543 [debug] ExAws: Request URL: "http://localhost:8000/" HEADERS: [{"Authorization", "AWS4-HMAC-SHA256 Credential=abcd/20200707/us-east-1/dynamodb/aws4_request,SignedHeaders=content-type;host;x-amz-content-sha256;x-amz-date;x-amz-target,Signature=fbf5bf9935c61a60d5d5f850dde0db91a68206f4f95df8a67b1682166dbd7d10"}, {"host", "localhost:8000"}, {"x-amz-date", "20200707T163957Z"}, {"x-amz-content-sha256", ""}, {"x-amz-target", "DynamoDB_20120810.Scan"}, {"content-type", "application/x-amz-json-1.0"}] BODY: "{\"TableName\":\"test_schema_migrations\"}" ATTEMPT: 1

12:39:57.556 [info]  Already up

and I confirmed that the table "test_schema_migrations" was created.

Was there more information in the error log that you received? Having the stacktrace would be very helpful in debugging this.

[vshev4enko]

sure

➜ mix ecto.migrate -r MyApp.RepoDynamo -n 0
Compiling 319 files (.ex)

Generated app

20:17:37.673 [debug] ExAws: Request URL: "https://dynamodb.us-east-1.amazonaws.com/" HEADERS: [{"host", "dynamodb.us-east-1.amazonaws.com"}, {"x-amz-date", "20200707T171737Z"}, {"x-amz-content-sha256", ""}, {"x-amz-target", "DynamoDB_20120810.ListTables"}, {"content-type", "application/x-amz-json-1.0"}] BODY: "{}" ATTEMPT: 1
{"attributes":{},"message":"2020-7-7 17:11:43 UTC [Ecto dynamo info] Ecto.Adapters.DynamoDB.Migration.execute_ddl: :create_if_not_exists (table)"}
{"attributes":{"table_name":":schema_migrations"},"message":"2020-7-7 17:11:44 UTC [Ecto dynamo info] Ecto.Adapters.DynamoDB.Migration.execute_ddl: create_if_not_exist: creating table"}

20:17:38.752 [debug] ExAws: Request URL: "https://dynamodb.us-east-1.amazonaws.com/" HEADERS: [{"host", "dynamodb.us-east-1.amazonaws.com"}, {"x-amz-date", "20200707T171738Z"}, {"x-amz-content-sha256", ""}, {"x-amz-target", "DynamoDB_20120810.CreateTable"}, {"content-type", "application/x-amz-json-1.0"}] BODY: "{\"AttributeDefinitions\":[{\"AttributeName\":\"version\",\"AttributeType\":\"N\"}],\"BillingMode\":\"PROVISIONED\",\"KeySchema\":[{\"AttributeName\":\"version\",\"KeyType\":\"HASH\"}],\"ProvisionedThroughput\":{\"ReadCapacityUnits\":1,\"WriteCapacityUnits\":1},\"TableName\":\"schema_migrations\"}" ATTEMPT: 1
{"attributes":{"Ecto.Adapters.DynamoDB.Migration.create_table_recursive-result":"{:ok, %{\"TableDescription\" => %{\"AttributeDefinitions\" => [%{\"AttributeName\" => \"version\", \"AttributeType\" => \"N\"}], \"CreationDateTime\" => 1594141904.058, \"ItemCount\" => 0, \"KeySchema\" => [%{\"AttributeName\" => \"version\", \"KeyType\" => \"HASH\"}], \"ProvisionedThroughput\" => %{\"NumberOfDecreasesToday\" => 0, \"ReadCapacityUnits\" => 1, \"WriteCapacityUnits\" => 1}, \"TableArn\" => \"arn:aws:dynamodb:region:id:table/schema_migrations\", \"TableId\" => \"778451ee-4846-441a-8eb0-edd26d989063\", \"TableName\" => \"schema_migrations\", \"TableSizeBytes\" => 0, \"TableStatus\" => \"CREATING\"}}}"},"message":"2020-7-7 17:11:44 UTC [Ecto dynamo info] Ecto.Adapters.DynamoDB.Migration.create_table_recursive: DynamoDB/ExAws response"}
{"attributes":{"table_name":"schema_migrations"},"message":"2020-7-7 17:11:44 UTC [Ecto dynamo info] Ecto.Adapters.DynamoDB.Migration.create_table_recursive: table created successfully."}
{"attributes":{"Ecto.Adapters.DynamoDB.execute-all-vars":{"lookup_fields":[],"table":"schema_migrations","updated_opts":["{:recursive, true}"]}},"message":"2020-7-7 17:11:44 UTC [Ecto dynamo info] Ecto.Adapters.DynamoDB.execute: :all"}

20:17:38.951 [debug] ExAws: Request URL: "https://dynamodb.us-east-1.amazonaws.com/" HEADERS: [{"host", "dynamodb.us-east-1.amazonaws.com"}, {"x-amz-date", "20200707T171738Z"}, {"x-amz-content-sha256", ""}, {"x-amz-target", "DynamoDB_20120810.Scan"}, {"content-type", "application/x-amz-json-1.0"}] BODY: "{\"TableName\":\"schema_migrations\"}" ATTEMPT: 1
** (ExAws.Error) ExAws Request Error!

{:error, {"ResourceNotFoundException", "Requested resource not found"}}

    (ex_aws) lib/ex_aws.ex:66: ExAws.request!/2
    (ecto_adapters_dynamodb) lib/ecto_adapters_dynamodb/query.ex:610: Ecto.Adapters.DynamoDB.Query.fetch_recursive/5
    (ecto_adapters_dynamodb) lib/ecto_adapters_dynamodb.ex:226: Ecto.Adapters.DynamoDB.execute/5
    (ecto) lib/ecto/repo/queryable.ex:192: Ecto.Repo.Queryable.execute/4
    (ecto) lib/ecto/repo/queryable.ex:17: Ecto.Repo.Queryable.all/3
    (ecto_sql) lib/ecto/migrator.ex:490: anonymous fn/3 in Ecto.Migrator.lock_for_migrations/4
    (ecto_sql) lib/ecto/migrator.ex:493: Ecto.Migrator.lock_for_migrations/4
    (ecto_sql) lib/ecto/migrator.ex:406: Ecto.Migrator.run/4
    (ecto_sql) lib/ecto/migrator.ex:142: Ecto.Migrator.with_repo/3
    (ecto_sql) lib/mix/tasks/ecto.migrate.ex:133: anonymous fn/5 in Mix.Tasks.Ecto.Migrate.run/2
    (elixir) lib/enum.ex:1940: Enum."-reduce/3-lists^foldl/2-0-"/3
    (ecto_sql) lib/mix/tasks/ecto.migrate.ex:121: Mix.Tasks.Ecto.Migrate.run/2
    (mix) lib/mix/task.ex:331: Mix.Task.run_task/3
    (mix) lib/mix/task.ex:365: Mix.Task.run_alias/3
    (mix) lib/mix/task.ex:292: Mix.Task.run/2
    (mix) lib/mix/cli.ex:79: Mix.CLI.run_task/2

if the table was created before migration i receive log as you posted above

[darrenklein]

Interesting - it did work for me, the table did not already exist. Can I trouble you with a few more questions?

• Are you running this against local development DynamoDB or production? If local, what version are you using? (you can find that in the README.txt file in the DDB directory)

• Can you share with me the configuration that you're using for :ecto_adapters_dynamodb, MyApp.RepoDynamo and :ecto_adapters_dynamodb? For example, the adapters test env configuration is

config :ecto_adapters_dynamodb, Ecto.Adapters.DynamoDB.TestRepo,
  migration_source: "test_schema_migrations",
  debug_requests: true,
  access_key_id: "abcd",
  secret_access_key: "1234",
  region: "us-east-1",
  dynamodb: [
    scheme: "http://",
    host: "localhost",
    port: 8000,
    region: "us-east-1"
  ]

config :ecto_adapters_dynamodb,
  dynamodb_local: true,
  log_levels: [],
  scan_tables: ["test_schema_migrations"]

• Can you share with me the contents of the file where you define MyApp.RepoDynamo (I'm guessing that would be repo_dynamo.ex)? For example, the adapter's test repo is defined as

defmodule Ecto.Adapters.DynamoDB.TestRepo do
  use Ecto.Repo,
    otp_app: :ecto_adapters_dynamodb,
    adapter: Ecto.Adapters.DynamoDB
end

[vshev4enko]

no problem

• I am running this against the production environment

• My config following

config :ecto_adapters_dynamodb,
  scan_tables: ["schema_migrations", "test_schema_migrations"]

config :ignited, Ignited.RepoDynamo,
  migration_source: "test_schema_migrations",
  debug_requests: true

• My repo_dynamo.ex

defmodule MyApp.RepoDynamo do
  use Ecto.Repo, otp_app: :my_app, adapter: Ecto.Adapters.DynamoDB
end

[darrenklein]

That all looks good to me (I assume you meant defmodule Ignited.RepoDynamo and otp_app: :ignited, but that's fine). If you're running this against production, I would suspect that what is happening is that the table is being created, just not "fast enough", which is causing the error. You'll notice that, when the migration is run, there are three functions that get called - ListTables, CreateTable, and Scan - the error is happening on the call to Scan - it runs immediately after CreateTable, but it can actually take several seconds for a table to be created, so it might not be fully formed by the time Scan is called.

This makes me realize that I forgot to ask an important question - even though there's an error, is the table actually being created?

[vshev4enko]

Table schema_migrations being created in case mix ecto.migrate -r MyApp.RepoDynamo -n 0
In case mix ecto.migrate -r MyApp.RepoDynamo only schema_migrations being created because raised the error.
Also, I have tried running the migration against local dynamodb, it works well independently i run mix ecto.migrate -r MyApp.RepoDynamo -n 0 or full mix ecto.migrate -r MyApp.RepoDynamo.
You are right regarding some time on creating table but i thought some attempt mechanism should solve these troubles.
I actually have no idea how following params work :migration_initial_wait, :migration_wait_exponent, :migration_max_wait, :migration_table_capacity.
I realized variables above works for another sort of errors like LimitExceededException

[darrenklein]

:migration_initial_wait, :migration_wait_exponent, :migration_max_wait, :migration_table_capacity won't resolve this specific problem, but they do address other related issues with DDB migrations - these are documented in the README, so that'll explain them better than I can here.

The issue here is that the migration process immediately tries to scan the tables after the migrations have been run, so the required fix would be to add retry logic for calling that scan function in the context of migrations (offhand, I don't know where that's called from) - but that might have other undesirable implications.

The error that you're encountering isn't preventing the table from being created, so that's good... once you've set up this initial schema migrations table, your other migrations should run without problems - you may find some of those options mentioned above help you to address any other timing-related issues you run into (for example, if you have two sequential migrations, one that creates a table and one that updates that same table, you could have a problem with the second migration if the table does not exist by the time it runs - :migration_initial_wait and :migration_max_wait could help you with those, see the docs).

Unfortunately, DynamoDB migrations are just a tricky thing to work with - I've had situations where a table is created/updated almost instantly, other times where it takes 30 seconds or more.

It would be nice to have a solution for this error you're running into, but we're not likely to address it in the near future - it's complex, the right course of action is not immediately clear, and the core dev team is very busy with other things at the moment. We'd be open to reviewing any suggestions or PRs you open.

[vshev4enko]

Thank you for so fast feedback. I am going to create some workaround in my release task. I will think about PR if there will be time.

[darrenklein]

Yes, I see how this could present some challenges with an automated release task...

Thank you so much for reporting this - let's keep this issue open so that we (or someone) may come up with a solution.