IeducarApi::Base::ApiError: 500 Internal Server Error

Olá, estou testando a integração entre o i-Educar e o i-Diário e me deparei com erro no processo de sincronização.

O processo de sincronização se inicia conforme documentação, começa a sincronizar alguns dados como por exemplo os cadastros das escolas porém em em terminado ponto apresenta o seguinte erro.

A minha instalação do i-Educar é uma instalação limpa e tem somente a importação do censo escolar realizada.

2021-06-02T14:02:14.532Z 54937 TID-oulw16fc4 SynchronizerBuilderWorker JID-da9309a71bf83a8db6f2e507 INFO: start
2021-06-02T14:02:14.545Z 54937 TID-oum0eeuew SynchronizerBuilderWorker JID-b7cc1865a0144e110a74bf29 INFO: done: 0.437 sec
2021-06-02T14:02:14.584Z 54937 TID-gnc2ro4io SynchronizerBuilderWorker JID-a9b4dec4b5b6592cb7b3a8a6 INFO: done: 0.425 sec
2021-06-02T14:02:14.597Z 54923 TID-ovbx8hpm4 SynchronizerBuilderEnqueueWorker JID-4ffaf01b114022062c784388 INFO: start
2021-06-02T14:02:14.620Z 54937 TID-oulzgvp30 SynchronizerBuilderWorker JID-b0e5adad96638e315aed38b9 INFO: done: 0.273 sec
2021-06-02T14:02:14.642Z 54937 TID-gnc2em1xw SynchronizerBuilderWorker JID-fc9334f4eead557b5dd41935 INFO: done: 0.395 sec
2021-06-02T14:02:14.713Z 54923 TID-ovbx8hpm4 SynchronizerBuilderEnqueueWorker JID-4ffaf01b114022062c784388 INFO: done: 0.117 sec
2021-06-02T14:02:14.718Z 54937 TID-oulub3ztw SynchronizerBuilderWorker JID-f287f1a3ef5e9c32ad956b86 INFO: done: 0.354 sec
2021-06-02T14:02:14.738Z 54937 TID-oum0eeuew SynchronizerBuilderWorker JID-276316ea653ebb14efda85ea INFO: start
2021-06-02T14:02:14.741Z 54937 TID-gnc2ro4io SynchronizerBuilderWorker JID-77cb0796b33510ccf981e06c INFO: start
2021-06-02T14:02:14.768Z 54937 TID-gnc2e8d2k SynchronizerBuilderWorker JID-5f99664db34f2030b5918df9 INFO: start
2021-06-02T14:02:14.840Z 54937 TID-oulw16fc4 SynchronizerBuilderWorker JID-da9309a71bf83a8db6f2e507 INFO: done: 0.309 sec
2021-06-02T14:02:14.923Z 54937 TID-gnc2ro4io SynchronizerBuilderWorker JID-77cb0796b33510ccf981e06c INFO: done: 0.182 sec
2021-06-02T14:02:15.002Z 54937 TID-oum0eeuew SynchronizerBuilderWorker JID-276316ea653ebb14efda85ea INFO: done: 0.264 sec
2021-06-02T14:02:15.107Z 54937 TID-gnc2e8d2k SynchronizerBuilderWorker JID-5f99664db34f2030b5918df9 INFO: done: 0.339 sec
2021-06-02T14:02:19.266Z 54937 TID-gnc2em074 SynchronizerExecuterWorker JID-141c9beb42075d6f2978a9fc INFO: done: 30.788 sec
2021-06-02T14:02:19.363Z 54937 TID-gnc2a8o7s SynchronizerExecuterWorker JID-1f4ae5172c22a42d5f59340d INFO: done: 29.851 sec
2021-06-02T14:02:23.251Z 54937 TID-gnc244xh4 SynchronizerExecuterWorker JID-8cc300556f814750126375d3 INFO: done: 34.749 sec
2021-06-02T14:02:26.129Z 54937 TID-oulzgvp30 StudentsUpdateUsesDifferentiatedExamRuleWorker JID-7e0fb6dde214271d2ef4465f INFO: start
2021-06-02T14:02:26.130Z 54937 TID-gnc2em1xw StudentsUpdateUsesDifferentiatedExamRuleWorker JID-4c763fae05c25ede32997fbd INFO: start
2021-06-02T14:02:26.143Z 54937 TID-oulw16fc4 SynchronizerExecuterWorker JID-34af4c0f4100961968d5a986 INFO: start
2021-06-02T14:02:26.148Z 54937 TID-oulub3ztw StudentsUpdateUsesDifferentiatedExamRuleWorker JID-4a97b5374f158963663e3fe0 INFO: start
2021-06-02T14:02:26.149Z 54937 TID-oulzgvp30 StudentsUpdateUsesDifferentiatedExamRuleWorker JID-7e0fb6dde214271d2ef4465f INFO: done: 0.019 sec
2021-06-02T14:02:26.150Z 54923 TID-ovbx8hpm4 SynchronizerBuilderEnqueueWorker JID-457d5086d97218793aef40ef INFO: start
2021-06-02T14:02:26.165Z 54937 TID-gnc2em1xw StudentsUpdateUsesDifferentiatedExamRuleWorker JID-4c763fae05c25ede32997fbd INFO: done: 0.034 sec
2021-06-02T14:02:26.195Z 54937 TID-oulw16fc4 SynchronizerExecuterWorker JID-34af4c0f4100961968d5a986 SidekiqUniqueJobs::Server::Middleware DIG-uniquejobs:51cfc8a4468b0f47e134396b993a1726 INFO: GET http://144.126.130.66/module/Api/Turma?access_key=3fa1d7cbc2c045c0a0b42c8b0ad1581e521031cb490a0a2a109f5f4925926e7410ea694c1b562955ccb6e44d210e3cf9a1f2203a4e401818d14210acaf6a8108&ano=2020&escola=3&instituicao_id=1&oper=get&resource=turmas-por-escola&secret_key=532e79872f2517f1e244e1ae1f939c72dccda74c7714f395c753271bf20fe0950aeeb003d9be37dee300b4af47ac9cfdfb3f3ddfd58d75d21d6fb7e5b09e7171 payload: {}
2021-06-02T14:02:26.220Z 54937 TID-oulub3ztw StudentsUpdateUsesDifferentiatedExamRuleWorker JID-4a97b5374f158963663e3fe0 INFO: done: 0.072 sec
2021-06-02T14:02:26.338Z 54937 TID-oulw16fc4 SynchronizerExecuterWorker JID-34af4c0f4100961968d5a986 SidekiqUniqueJobs::Server::Middleware DIG-uniquejobs:51cfc8a4468b0f47e134396b993a1726 ERROR: Failed to execute job, restoring lock
2021-06-02T14:02:26.341Z 54937 TID-oulw16fc4 SynchronizerExecuterWorker JID-34af4c0f4100961968d5a986 INFO: fail: 0.198 sec
2021-06-02T14:02:26.344Z 54937 TID-oulw16fc4 WARN: {“context”:“Job raised exception”,“job”:{“class”:“SynchronizerExecuterWorker”,“args”:[{“klass”:“ClassroomsSynchronizer”,“synchronization_id”:1,“worker_batch_id”:1,“entity_id”:1,“year”:“2020”,“unity_api_code”:“3”,“filtered_by_year”:true,“filtered_by_unity”:true,“current_years”:true,“worker_state_id”:42}],“retry”:3,“queue”:“synchronizer”,“unique”:“until_and_while_executing”,“dead”:false,“jid”:“34af4c0f4100961968d5a986”,“created_at”:1622642509.2852948,“lock_timeout”:0,“lock_expiration”:null,“unique_prefix”:“uniquejobs”,“unique_args”:[{“klass”:“ClassroomsSynchronizer”,“synchronization_id”:1,“worker_batch_id”:1,“entity_id”:1,“year”:“2020”,“unity_api_code”:“3”,“filtered_by_year”:true,“filtered_by_unity”:true,“current_years”:true,“worker_state_id”:42}],“unique_digest”:“uniquejobs:51cfc8a4468b0f47e134396b993a1726:RUN”,“enqueued_at”:1622642546.140011,“error_message”:“500 Internal Server Error”,“error_class”:“IeducarApi::Base::ApiError”,“failed_at”:1622642523.2878203,“retry_count”:1,“retried_at”:1622642546.340812},“jobstr”:"{“class”:“SynchronizerExecuterWorker”,“args”:[{“klass”:“ClassroomsSynchronizer”,“synchronization_id”:1,“worker_batch_id”:1,“entity_id”:1,“year”:“2020”,“unity_api_code”:“3”,“filtered_by_year”:true,“filtered_by_unity”:true,“current_years”:true,“worker_state_id”:42}],“retry”:3,“queue”:“synchronizer”,“unique”:“until_and_while_executing”,“dead”:false,“jid”:“34af4c0f4100961968d5a986”,“created_at”:1622642509.2852948,“lock_timeout”:0,“lock_expiration”:null,“unique_prefix”:“uniquejobs”,“unique_args”:[{“klass”:“ClassroomsSynchronizer”,“synchronization_id”:1,“worker_batch_id”:1,“entity_id”:1,“year”:“2020”,“unity_api_code”:“3”,“filtered_by_year”:true,“filtered_by_unity”:true,“current_years”:true,“worker_state_id”:42}],“unique_digest”:“uniquejobs:51cfc8a4468b0f47e134396b993a1726”,“enqueued_at”:1622642546.140011,“error_message”:“could not obtain a database connection within 5.000 seconds (waited 5.002 seconds)”,“error_class”:“ActiveRecord::ConnectionTimeoutError”,“failed_at”:1622642523.2878203,“retry_count”:0}"}
2021-06-02T14:02:26.345Z 54937 TID-oulw16fc4 WARN: IeducarApi::Base::ApiError: 500 Internal Server Error
2021-06-02T14:02:26.345Z 54937 TID-oulw16fc4 WARN: /var/www/i-diario/app/services/ieducar_api/base.rb:103:in rescue in request' /var/www/i-diario/app/services/ieducar_api/base.rb:89:in request’
/var/www/i-diario/app/services/ieducar_api/base.rb:34:in fetch' /var/www/i-diario/app/services/ieducar_api/classrooms.rb:12:in fetch’
/var/www/i-diario/app/services/ieducar_synchronizers/classrooms_synchronizer.rb:5:in synchronize!' /var/www/i-diario/app/services/ieducar_synchronizers/base_synchronizer.rb:19:in synchronize!’
/var/www/i-diario/app/workers/ieducar/synchronizer_executer_worker.rb:9:in block in perform' /usr/local/rvm/gems/ruby-2.4.10/bundler/gems/activerecord-connections-b2a704ff10c4/lib/active_record/connections.rb:32:in using_connection’
/var/www/i-diario/app/models/entity.rb:22:in using_connection' /var/www/i-diario/app/workers/ieducar/synchronizer_executer_worker.rb:5:in perform’
/usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-5.0.3/lib/sidekiq/processor.rb:199:in execute_job' /usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-5.0.3/lib/sidekiq/processor.rb:170:in block (2 levels) in process’
/usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-5.0.3/lib/sidekiq/middleware/chain.rb:128:in block in invoke' /usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-5.0.3/lib/sidekiq/middleware/server/active_record.rb:15:in call’
/usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-5.0.3/lib/sidekiq/middleware/chain.rb:130:in block in invoke' /usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-unique-jobs-6.0.22/lib/sidekiq_unique_jobs/server/middleware.rb:34:in block (2 levels) in call’
/usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-unique-jobs-6.0.22/lib/sidekiq_unique_jobs/lock/until_and_while_executing.rb:21:in block (2 levels) in execute' /usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-unique-jobs-6.0.22/lib/sidekiq_unique_jobs/lock/while_executing.rb:38:in execute’
/usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-unique-jobs-6.0.22/lib/sidekiq_unique_jobs/lock/until_and_while_executing.rb:21:in block in execute' /usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-unique-jobs-6.0.22/lib/sidekiq_unique_jobs/lock/until_and_while_executing.rb:37:in lock_on_failure’
/usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-unique-jobs-6.0.22/lib/sidekiq_unique_jobs/lock/until_and_while_executing.rb:20:in execute' /usr/local/rvm/gems/ruby-2.4.10/gems/sidekiq-unique-jobs-6.0.22/lib/sidekiq_unique_jobs/server/middleware.rb:33:in block in call’

Colocou os DOIS processos para executar? Mudou a forma de iniciar o sidekiq nas versões mais recentes

Obrigado pelo retorno @robson

Coloquei sim os dois processos para executar, são eles:

# Processo 1 (Responsavel pela sincronizacao com o i-educar)
echo "===> INICIANDO PROCESSO DE SINCRONIZACAO COM O i-Educar"
bundle exec sidekiq -q synchronizer_enqueue_next_job -c 1 -d --logfile log/sidekiq.log

# Processo 2 (Responsavel pelos outros jobs)
echo "===> INICIANDO PROCESSO RESPONSAVEL PELOS OUTROS JOBS"
bundle exec sidekiq -c 10 -d --logfile log/sidekiq.log

Após isso, configurei as KEYS e obtenho o erro mencionado ao tentar sincronizar, a sincronização apresenta o erro por volta dos 83%

Pelo log, parece que foi problema de conexão.

Acho difícil, o i-Educar e i-Diário estão na mesma máquina incluindo o PostgreSQL.

Ele Sincroniza as escolas e outros itens, mais chega nesse ponto e sempre da o mesmo erro. Como se fosse algum dado que ele não conseguisse carregar ou algo do tipo.

Também estou com problemas de sincronização (envio de avaliações). Parece que sejam bugs.

1 Curtida

Me chamou atenção essa informação:

Tens alguma configuração de timeout no postgres? Pool do banco de dados menor que a quantidade de jobs?

1 Curtida

Está no valor default, não achei que seria necessário aumentar esse valor, mais posso fazer o teste e volto e aviso aqui.

Muito obrigado @tiago.camargo pelo retorno.

Ajustei o pool e o max de conexão porém continua tendo erro sempre na sincronização das Turmas

@tiago.camargo, alguma ideia ou dica do que pode ser feito para solucionar o problema?


2021-06-10T01:51:20.374Z 102731 TID-gmubqp118 SynchronizerExecuterWorker JID-4a331432324e0ac1cea73cdd INFO: start
2021-06-10T01:51:20.394Z 102731 TID-gmubqp118 SynchronizerExecuterWorker JID-4a331432324e0ac1cea73cdd SidekiqUniqueJobs::Server::Middleware DIG-uniquejobs:3a858d233d83459ebb4e692aff905d68 INFO: GET http://143.198.125.84/module/Api/Turma?access_key=9e253aa9f2bab4d235f6a8df75ab617c431c9c2eaf61bb1b77ac99d99effdbb2d345f9df35584a523b25fa4c41be1c9494d93902fec1bacd925fc5b80dfe30b8&ano=2021&escola=7&instituicao_id=1&oper=get&resource=turmas-por-escola&secret_key=1d9531fabdbf0742913965729092fbd6141d340bfcd32f28ac74475720218af6060f48343b69a5f21622c161f33b4ada463862c6808197d94b0399a47db534e9 payload: {}
2021-06-10T01:51:20.431Z 102731 TID-gmubqp118 SynchronizerExecuterWorker JID-4a331432324e0ac1cea73cdd SidekiqUniqueJobs::Server::Middleware DIG-uniquejobs:3a858d233d83459ebb4e692aff905d68 ERROR: Failed to execute job, restoring lock
2021-06-10T01:51:20.443Z 102731 TID-gmubqp118 SynchronizerExecuterWorker JID-4a331432324e0ac1cea73cdd INFO: fail: 0.069 sec
2021-06-10T01:51:20.443Z 102731 TID-gmubqp118 WARN: {"context":"Job raised exception","job":{"class":"SynchronizerExecuterWorker","args":[{"klass":"ClassroomsSynchronizer","synchronization_id":3,"worker_batch_id":3,"entity_id":1,"year":"2021","unity_api_code":"7","filtered_by_year":true,"filtered_by_unity":true,"current_years":true,"worker_state_id":563}],"retry":3,"queue":"synchronizer","unique":"until_and_while_executing","dead":false,"jid":"4a331432324e0ac1cea73cdd","created_at":1623289604.1031635,"lock_timeout":0,"lock_expiration":null,"unique_prefix":"uniquejobs","unique_args":[{"klass":"ClassroomsSynchronizer","synchronization_id":3,"worker_batch_id":3,"entity_id":1,"year":"2021","unity_api_code":"7","filtered_by_year":true,"filtered_by_unity":true,"current_years":true,"worker_state_id":563}],"unique_digest":"uniquejobs:3a858d233d83459ebb4e692aff905d68:RUN","enqueued_at":1623289880.3743873,"error_message":"500 Internal Server Error","error_class":"IeducarApi::Base::ApiError","failed_at":1623289623.5487661,"retry_count":3,"retried_at":1623289880.4329913},"jobstr":"{\"class\":\"SynchronizerExecuterWorker\",\"args\":[{\"klass\":\"ClassroomsSynchronizer\",\"synchronization_id\":3,\"worker_batch_id\":3,\"entity_id\":1,\"year\":\"2021\",\"unity_api_code\":\"7\",\"filtered_by_year\":true,\"filtered_by_unity\":true,\"current_years\":true,\"worker_state_id\":563}],\"retry\":3,\"queue\":\"synchronizer\",\"unique\":\"until_and_while_executing\",\"dead\":false,\"jid\":\"4a331432324e0ac1cea73cdd\",\"created_at\":1623289604.1031635,\"lock_timeout\":0,\"lock_expiration\":null,\"unique_prefix\":\"uniquejobs\",\"unique_args\":[{\"klass\":\"ClassroomsSynchronizer\",\"synchronization_id\":3,\"worker_batch_id\":3,\"entity_id\":1,\"year\":\"2021\",\"unity_api_code\":\"7\",\"filtered_by_year\":true,\"filtered_by_unity\":true,\"current_years\":true,\"worker_state_id\":563}],\"unique_digest\":\"uniquejobs:3a858d233d83459ebb4e692aff905d68\",\"enqueued_at\":1623289880.3743873,\"error_message\":\"500 Internal Server Error\",\"error_class\":\"IeducarApi::Base::ApiError\",\"failed_at\":1623289623.5487661,\"retry_count\":2,\"retried_at\":1623289756.743126}"}
2021-06-10T01:51:20.443Z 102731 TID-gmubqp118 WARN: IeducarApi::Base::ApiError: 500 Internal Server Error
2021-06-10T01:51:20.444Z 102731 TID-gmubqp118 WARN: /var/www/idiario/app/services/ieducar_api/base.rb:103:in `rescue in request'
/var/www/idiario/app/services/ieducar_api/base.rb:89:in `request'
/var/www/idiario/app/services/ieducar_api/base.rb:34:in `fetch'
/var/www/idiario/app/services/ieducar_api/classrooms.rb:12:in `fetch'

Bom que resolveu a questão do pool do banco.

No log do i-educar você vai encontrar o motivo que deu esse erro 500.

1 Curtida

Olá @tiago.camargo, no log do i-educar mesmo habilitando o ambiente como local e ativando o modo debug o motivo não é apresentado.

Um dos itens que peguei no log foi o seguinte erro, a tabela existe no ieducar, no schema public, porém ela não tem dados, pois como já informado em outros post, essa versão do i-educar não insere dados no settings para serem apresentados na funcionalidade: Início → Configurações → Configurações de sistema

Acredita que pode ter alguma relação ?


[2021-06-09 23:56:24] ERROR: SQLSTATE[42P01]: Undefined table: 7 ERROR:  relation "settings" does not exist
LINE 1: select * from "settings"
                      ^ (SQL: select * from "settings") {"exception":"[object] (Illuminate\\Database\\QueryException(code: 42P01): SQLSTATE[42P01]: Undefined table: 7 ERROR:  relation \"settings\" does not exist
LINE 1: select * from \"settings\"
                      ^ (SQL: select * from \"settings\") at /var/www/ieducar/vendor/laravel/framework/src/Illuminate/Database/Connection.php:685)
[stacktrace]
#0 /var/www/ieducar/vendor/laravel/framework/src/Illuminate/Database/Connection.php(645): Illuminate\\Database\\Connection->runQueryCallback()
#1 /var/www/ieducar/vendor/laravel/framework/src/Illuminate/Database/Connection.php(353): Illuminate\\Database\\Connection->run()
#2 /var/www/ieducar/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(2351): Illuminate\\Database\\Connection->select()
#3 /var/www/ieducar/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(2339): Illuminate\\Database\\Query\\Builder->runSelect()
#4 /var/www/ieducar/vendor/laravel/framework/src/Illuminate/Database/Query/Builder.php(2905): Illuminate\\Database\\Query\\Builder->Illuminate\\Database\\Query\\{closure}()

Dá uma olhada se isso pode te ajudar: Menu Configurações / Configurações de sistema · Issue #751 · portabilis/i-educar · GitHub