Strange indexer sync behavior

Question

Strange indexer sync behavior

puppetninja opened this issue 2 years ago · 21 comments

I am see the output like this while running an indexer on ghostnet

Looks like syncing is still going on while it get 404 response from rpc endpoint ?

Answer 1 · 2023-03-27T15:07:02.000Z

Hi! That has nothing to do with the indexer, but with the RPC you are using.

What you see (or will see if enable "Debug" log level) in the logs is:

the indexer has found a new block;
the indexer tries to fetch the new block;
the RPC responds with 404;
the indexer throws an exception, and...;
and tries to fetch the new block again;
the RPC responds with 200;
the indexer applies the block.

So, on the indexer side that's an absolutely normal behavior.

I don't know what's wrong with your RPC, but can guess, that you are using RPC with load balancing, i.e. with multiple nodes behind. So, for example, a request to chain's header (to check if there is a new block) is processed by one node, but the following request to the new block is processed by another node, and if that node is not yet synced up, it responds with 404.

Answer 2 · 2023-03-27T16:36:48.000Z

Ah, okay, makes sense and thanks for the reply. I am using public node here
https://tezostaquito.io/docs/rpc_nodes/
but indeed I don't know what is behind the lb

Answer 3 · 2023-03-27T16:49:26.000Z

You're welcome ;)
And just to make it clear, there is nothing to worry about. Such exceptions are harmless to the indexer.

Answer 4 · 2023-03-28T12:34:57.000Z

Hi @Groxan can you tell me how to enable debug on tzkt ?

Answer 5 · 2023-03-28T12:35:45.000Z

I am running sync issue again with different symptoms

Answer 6 · 2023-03-28T12:37:32.000Z

Is this related to DB operations or tzkt request timeout ?

Answer 7 · 2023-03-28T12:44:53.000Z

puppetninja commented 2 years ago

Answer 8 · 2023-03-28T12:45:23.000Z

I see this on DB even after restart the pod, could this be something from tzkt ?

Answer 9 · 2023-03-28T12:49:20.000Z

so I switch off the tzkt, and restarted the db it looks good to me

Answer 10 · 2023-03-28T12:50:39.000Z

puppetninja commented 2 years ago

Answer 11 · 2023-03-28T12:51:07.000Z

Then I see this #146 (comment)
As soon as I switch on tzkt

Answer 12 · 2023-03-28T13:36:54.000Z

I see entity framework is display warning message

Answer 13 · 2023-03-28T14:54:11.000Z

Log level can be configured here (set to "Debug").
That's a DB timeout. You can configure (increase) it by setting the command timeout= value in the connection string via appsettings.json or via env vars.
EF's warning is normal.

Answer 14 · 2023-03-28T15:20:57.000Z

Thanks @Groxan really appreicate it !!

Answer 15 · 2023-03-30T17:37:04.000Z

Sorry for continue using this post.

I found out i'm facing some similar problem, which also cause my DB.

warn: Microsoft.EntityFrameworkCore.Query[10103]
      The query uses the 'First'/'FirstOrDefault' operator without 'OrderBy' and filter operators. This may lead to unpredictable results.
fail: Microsoft.EntityFrameworkCore.Database.Command[20102]
      Failed executing DbCommand (30,837ms) [Parameters=[@__8__locals1_block_Level_1='?' (DbType = Int32)], CommandType='Text', CommandTimeout='30']
      SELECT t."Id", t."AllocationFee", t."Amount", t."BakerFee", t."BigMapUpdates", t."Counter", t."Entrypoint", t."Errors", t."EventsCount", t."GasLimit", t."GasUsed", t."InitiatorId", t."InternalDelegations", t."InternalOperations", t."InternalOriginations", t."InternalTransactions", t."JsonParameters", t."Level", t."Nonce", t."OpHash", t."RawParameters", t."ResetDeactivation", t."SenderCodeHash", t."SenderId", t."Status", t."StorageFee", t."StorageId", t."StorageLimit", t."StorageUsed", t."SubIds", t."TargetCodeHash", t."TargetId", t."Timestamp", t."TokenTransfers"
      FROM "TransactionOps" AS t
      WHERE t."TargetId"::bigint = 4275130 AND t."Status" = 1 AND t."Entrypoint" = 'transfer' AND (t."TokenTransfers" IS NULL) AND t."Level" < @__8__locals1_block_Level_1
fail: Microsoft.EntityFrameworkCore.Query[10100]
      An exception occurred while iterating over the results of a query for context type 'Tzkt.Data.TzktContext'.
      System.InvalidOperationException: An exception has been raised that is likely due to a transient failure.
       ---> Npgsql.NpgsqlException (0x80004005): Exception while reading from stream
       ---> System.TimeoutException: Timeout during reading attempt
         at Npgsql.Internal.NpgsqlConnector.<ReadMessage>g__ReadMessageLong|233_0(NpgsqlConnector connector, Boolean async, DataRowLoadingMode dataRowLoadingMode, Boolean readingNotifications, Boolean isReadingPrependedMessage)
         at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
         at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
         at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
         --- End of inner exception stack trace ---
         at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
      System.InvalidOperationException: An exception has been raised that is likely due to a transient failure.
       ---> Npgsql.NpgsqlException (0x80004005): Exception while reading from stream
       ---> System.TimeoutException: Timeout during reading attempt
         at Npgsql.Internal.NpgsqlConnector.<ReadMessage>g__ReadMessageLong|233_0(NpgsqlConnector connector, Boolean async, DataRowLoadingMode dataRowLoadingMode, Boolean readingNotifications, Boolean isReadingPrependedMessage)
         at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
         at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
         at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
         --- End of inner exception stack trace ---
         at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
fail: Tzkt.Sync.Services.Observer[0]
      Failed to apply updates
      System.InvalidOperationException: An exception has been raised that is likely due to a transient failure.
       ---> Npgsql.NpgsqlException (0x80004005): Exception while reading from stream
       ---> System.TimeoutException: Timeout during reading attempt
         at Npgsql.Internal.NpgsqlConnector.<ReadMessage>g__ReadMessageLong|233_0(NpgsqlConnector connector, Boolean async, DataRowLoadingMode dataRowLoadingMode, Boolean readingNotifications, Boolean isReadingPrependedMessage)
         at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
         at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
         at Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
         at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
         --- End of inner exception stack trace ---
         at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.Query.Internal.SingleQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
         at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable`1 source, CancellationToken cancellationToken)
         at Microsoft.EntityFrameworkCore.EntityFrameworkQueryableExtensions.ToListAsync[TSource](IQueryable`1 source, CancellationToken cancellationToken)
         at Tzkt.Sync.Protocols.Proto5.TokensCommit.Apply(Block block, List`1 updates) in /app/Tzkt.Sync/Protocols/Handlers/Proto5/Commits/TokensCommit.cs:line 136
         at Tzkt.Sync.Protocols.Proto15Handler.Commit(JsonElement block) in /app/Tzkt.Sync/Protocols/Handlers/Proto15/Proto15Handler.cs:line 263
         at Tzkt.Sync.ProtocolHandler.CommitBlock(Int32 head) in /app/Tzkt.Sync/Protocols/ProtocolHandler.cs:line 76
         at Tzkt.Sync.ProtocolHandler.CommitBlock(Int32 head) in /app/Tzkt.Sync/Protocols/ProtocolHandler.cs:line 129
         at Tzkt.Sync.Services.Observer.ApplyUpdatesAsync(CancellationToken cancelToken) in /app/Tzkt.Sync/Services/Observer/Observer.cs:line 183
         at Tzkt.Sync.Services.Observer.ExecuteAsync(CancellationToken cancelToken) in /app/Tzkt.Sync/Services/Observer/Observer.cs:line 66

I have no idea what is this problem, please help. Thank you.

PS: I just update my rpc node to 16.1 version, and current tzkt version to 1.12.0

Answer 16 · 2023-03-30T18:01:30.000Z

looks like similar issue I had, did you increase the command timeout like mentioned above ? @joslee7410

Answer 17 · 2023-03-31T01:57:55.000Z

@puppetninja may i know, any suggested timeout numbers? I saw currently default is 600.

Answer 18 · 2023-03-31T03:55:03.000Z

I set to 3600, but still having the same problem.

I did remove those 3 containers (tzkt-db, tzkt-sync, tzkt-api), and "make open" again for creating them.

Answer 19 · 2023-03-31T09:23:05.000Z

@joslee7410 600 works for me, your tzkt is having same output like what I had, your db is logging similar like what I pasted above ?

Answer 20 · 2023-03-31T10:55:22.000Z

@joslee7410 Right, according to

Failed executing DbCommand (30,837ms) [Parameters=[...], CommandType='Text', CommandTimeout='30']

it's a 30 sec DB timeout, so increasing it will help (600 sec should be enough). 30 sec is a default Postgres' value, so you likely have connection string with no command timeout= specified.

Note that settings passed via env vars (e.g. in the docker-compose file) have a higher priority and override settings specified in the appsettings.json file, so make sure you configure it in the right place.

Answer 21 · 2023-03-31T11:49:34.000Z

Ahhh, thanks for the help both of you @puppetninja and @Groxan , cause i'm using old docker-compose, didn't bring the CommandTimeout env vars.

now worked well. Thank you.