Processo age7 não sendo iniciado

transparencia-mg / age7

https://transparencia-mg.github.io/age7/

1 stars 2 forks source link

Processo age7 não sendo iniciado #192

Closed gabrielbdornas closed 1 year ago

gabrielbdornas commented 1 year ago

Em 29/03/2023 reiniciei o cron job seguindo as orientações deste post.

/etc/init.d/cron restart

Monitorar se processo será iniciado corretamente em 30/03/2023.

Também removi a imagem gabrielbdornas/dtamg-age7 para certificar a utilização da nova dtamg/age7.

gabrielbdornas commented 1 year ago

Conferência realizada em 30/03/2023 mostrou que processo não rodou.

Utilizado comando sudo grep CRON /var/log/syslog para verificar log do CRON que mostrou repetidamente:

Mar 30 13:44:01 cge-pda CRON[3023392]: (root) CMD (/usr/sbin/ntpdate -u 10.15.135.1)
Mar 30 13:44:01 cge-pda CRON[3023391]: (root) CMD (/opt/scripts/permissao.sh)
Mar 30 13:44:07 cge-pda CRON[3023389]: (CRON) info (No MTA installed, discarding output)

Este post Stackoverflow sugere algum problema nos caracteres de final de linha. De fato isso pode ter ocorrido caso eu tenha modificado os arquivos docker.sh e all.sh no windows (máquina CAMG) e não em meu computador pessoal (linux). Tentei salvar os arquivos docker.sh e all.sh removendo linhas e espaços no linux.

Verificar se processo rodou em 31/03/2023. Caso contrário tentar esta alternativa.

Obs.: Processo iniciado manualmente na mesma data.

gabrielbdornas commented 1 year ago

Processo continua não rodando em 03/04/2023. Mudei a permissão de execução do arquivo, docker.sh, conforme sugerido neste post:

chmod +x docker-entrypoint.sh

Reconstruir a imagem dtamg/age7:latest:

Primeira tentativa não funcionou:

docker images
docker rmi <image-id>
docker build . --file Dockerfile --tag dtamg/age7:latest

Expectativa da configuração criada no arquivo ~/.docker/config.json, conforme sugerido nesta anotação não funcionou.

Segunda tentativa não funcionou:

Passei as informações da proxy diretamente no comando (via flag --build-arg), conforme sugerido aqui:

sudo docker build --build-arg HTTP_PROXY=<PROXY> --build-arg HTTPS_PROXY=<PROXY> . --file Dockerfile --tag dtamg/age7:latest

Terceira tentativa:
- Configurei docker para rodar sem sudo.
- Adicionei usuário gabriel.dornas como pasta report porque estava recebendo uma mensagem de que o arquivo index.htm não poderia ser lido.
- Rodei novamente docker build . --file Dockerfile --tag dtamg/age7:latest e funcionou

Conferir se processo rodou em 04/04/2023.

gabrielbdornas commented 1 year ago

Processo não rodando em 10/04/2023. Adicionei o usuário gabriel.dornas no arquivo docker.sh via sudo chown gabriel.dornas docker.sh, conforme demonstrado aqui.

gabriel.dornas@cge-pda:~/age7$ ls -la
total 12936
drwxrwxr-x 14 gabriel.dornas acessossh     4096 Apr  4 01:11 .
drwxrwxr-x  7 root           acessossh     4096 Apr  3 21:31 ..
-rw-r--r--  1 root           acessossh      331 Feb 16 22:29 age7.R
-rw-r--r--  1 root           acessossh      226 Feb 16 22:29 age7.Rproj
-rw-r--r--  1 root           acessossh    33216 Feb 16 22:29 age7.yaml
-rw-r--r--  1 root           acessossh      405 Feb 16 22:29 all.bat
-rwxr-xr-x  1 root           acessossh      448 Apr  3 20:53 all.sh
drwxr-xr-x 15 root           acessossh     4096 Apr  4 01:14 build_datasets
-rw-r--r--  1 root           acessossh        0 Feb 16 22:29 CHANGELOG.md
-rw-r--r--  1 root           acessossh     1334 Feb 16 22:29 config.mk
-rw-r--r--  1 root           acessossh        0 Feb 16 22:29 CONTRIBUTING.md
drwxrwxr-x  4 gabriel.dornas acessossh    16384 Feb 14 02:16 data
-rw-r--r--  1 gabriel.dornas acessossh 12918223 Apr  4 01:04 datapackage.json
-rw-r--r--  1 root           acessossh     2285 Feb 16 22:29 datapackage.Rmd
-rw-r--r--  1 root           acessossh   119263 Feb 16 22:29 datapackage.yaml
drwxrwxr-x 15 gabriel.dornas acessossh     4096 Aug 31  2022 datasets
-rw-r--r--  1 root           acessossh     1450 Feb 16 22:29 Dockerfile
-rwxr-xr-x  1 gabriel.dornas acessossh      419 Apr  3 20:53 docker.sh
drwxrwsrwx  8 gabriel.dornas acessossh     4096 Apr 10 19:14 .git
drwxrwxr-x  3 gabriel.dornas acessossh     4096 Aug 31  2022 .github
-rw-r--r--  1 root           acessossh      237 Feb 16 22:29 .gitignore
-rw-r--r--  1 root           acessossh      553 Feb 16 22:29 index.md
-rw-r--r--  1 root           acessossh     5276 Feb 16 22:29 INSTALL.md
drwxr-xr-x  3 root           acessossh     4096 Feb 16 18:16 .local
drwxrwxr-x  7 gabriel.dornas acessossh     4096 Apr  3 21:31 logs
-rw-r--r--  1 root           acessossh     3678 Feb 16 22:29 Makefile
-rw-r--r--  1 root           acessossh     2593 Feb 16 22:29 README.md
-rw-r--r--  1 root           acessossh    19510 Feb 16 22:29 renv.lock
drwxr-xr-x  2 gabriel.dornas acessossh     4096 Apr  3 21:31 report
-rw-r--r--  1 root           acessossh      144 Feb 16 22:29 requirements.txt
-rw-r--r--  1 root           acessossh      334 Feb 16 22:29 run.sh
drwxrwxr-x  2 gabriel.dornas acessossh    16384 Feb 16 22:29 schemas
drwxrwxr-x  5 gabriel.dornas acessossh     4096 Feb 16 22:29 scripts
drwxrwxr-x  2 gabriel.dornas acessossh     4096 Feb 16 22:29 templates
drwxrwxr-x  3 gabriel.dornas acessossh     4096 Feb 16 22:29 tests

gabrielbdornas commented 1 year ago

Processo rodou em 11/04/2023, mas apresentou o seguinte erro durante as rotinas de teste em R:

Rscript --verbose -e "testthat::test_file('tests/testthat/test_dm_contratado.R', stop_on_failure=TRUE)" 2> logs/tests/test_dm_contratado.Rout

══ Testing test_dm_contratado.R ════════════════════════════════════════════════
[ FAIL 0 | WARN 0 | SKIP 0 | PASS 2 ] Done!
Rscript --verbose -e "testthat::test_file('tests/testthat/test_dm_favorecido.R', stop_on_failure=TRUE)" 2> logs/tests/test_dm_favorecido.Rout

══ Testing test_dm_favorecido.R ════════════════════════════════════════════════
[ FAIL 1 | WARN 1 | SKIP 0 | PASS 6 ]

── Error (test_dm_favorecido.R:33:3): Anonimização prêmios lotéricos ───────────
Error in `bmerge(i, x, leftcols, rightcols, roll, rollends, nomatch, mult,
    ops, verbose = verbose)`: Incompatible join types: x.id_unidade_orc (logical) and i.id_unidade_orc (integer)
Backtrace:
 1. base::unlist(map(2002:2022, get_id_favorecido_premios_lotericos)) test_dm_favorecido.R:33:2
 2. purrr::map(2002:2022, get_id_favorecido_premios_lotericos)
 3. .f(.x[[i]], ...)
 5. data.table:::`[.data.table`(dm_unidade_orc, ft_despesa, on = "id_unidade_orc") test_dm_favorecido.R:24:4
 6. data.table:::bmerge(...)

── Warning (test_dm_favorecido.R:51:3): Anonimização hanseniase 2021 ───────────
Python '/work_dir/python' was requested but '/usr/local/bin/python' was loaded instead (see reticulate::py_config() for more information)
Backtrace:
  1. dtamg::flatten_resource(...) test_dm_favorecido.R:51:2
  3. reticulate:::`$.python.builtin.module`(frictionless, "Package")
  4. reticulate:::py_resolve_module_proxy(x)
  9. reticulate::import(module)
 10. reticulate:::ensure_python_initialized(required_module = module)
 11. reticulate:::initialize_python(required_module, use_environment)
 12. (function() {...

[ FAIL 1 | WARN 1 | SKIP 0 | PASS 6 ]

Os arquivo logs/tests/test_dm_contratado.Rout e logs/tests/test_dm_favorecido.Rout apresentaram o mesmo tipo de informação:

gabriel.dornas@cge-pda:~/age7$ cat logs/tests/test_dm_contratado.Rout
running
  '/usr/lib/R/bin/R --no-echo --no-restore -e testthat::test_file('tests/testthat/test_dm_contratado.R', stop_on_failure=TRUE)'

Attaching package: ‘validate’

The following object is masked from ‘package:testthat’:

    compare

Attaching package: ‘purrr’

The following object is masked from ‘package:data.table’:

    transpose

The following object is masked from ‘package:testthat’:

    is_null

Estes testes conferem as anonimizações. Caso algum erro seja identificado nestes testes a execução é interrompida, portanto os conjuntos não foram atualizados no portal.

Solicitarei auxilio de @fjuniorr para tentar solucionar o problema.

fjuniorr commented 1 year ago

Lendo a mensagem de erro

Error in `bmerge(i, x, leftcols, rightcols, roll, rollends, nomatch, mult,
    ops, verbose = verbose)`: Incompatible join types: x.id_unidade_orc (logical) and i.id_unidade_orc (integer)
Backtrace:
 1. base::unlist(map(2002:2022, get_id_favorecido_premios_lotericos)) test_dm_favorecido.R:33:2
 2. purrr::map(2002:2022, get_id_favorecido_premios_lotericos)
 3. .f(.x[[i]], ...)
 5. data.table:::`[.data.table`(dm_unidade_orc, ft_despesa, on = "id_unidade_orc") test_dm_favorecido.R:24:4
 6. data.table:::bmerge(...)

vale a pena checar primeiro se as colunas dm_unidade_orc.id_unidade_orc e ft_despesa.id_unidade_orc estão com o mesmo tipo.

gabrielbdornas commented 1 year ago

Lendo a mensagem de erro

Error in `bmerge(i, x, leftcols, rightcols, roll, rollends, nomatch, mult,
    ops, verbose = verbose)`: Incompatible join types: x.id_unidade_orc (logical) and i.id_unidade_orc (integer)
Backtrace:
 1. base::unlist(map(2002:2022, get_id_favorecido_premios_lotericos)) test_dm_favorecido.R:33:2
 2. purrr::map(2002:2022, get_id_favorecido_premios_lotericos)
 3. .f(.x[[i]], ...)
 5. data.table:::`[.data.table`(dm_unidade_orc, ft_despesa, on = "id_unidade_orc") test_dm_favorecido.R:24:4
 6. data.table:::bmerge(...)

vale a pena checar primeiro se as colunas dm_unidade_orc.id_unidade_orc e ft_despesa.id_unidade_orc estão com o mesmo tipo.

@fjuniorr, verifiquei no banco e os tipo de dados das colunas são numéricos:

Coluna id_favorecido da tabela dm_favorecido com o tipo de dado bigint:

Coluna id_favorecido nas tabelas ft_despesa com o tipo de dado decimal:

Segundo Márcia este não é o problema e sim a criação de um novo índice, já que a tabela dm_favorecido está com quase 1.2 M de registros. Após o índice criado o join das duas tabelas, que não estava sendo executando, funcionou:

Coloquei o processo para rodar as 16:00 horas de hoje, 11/04/2023. Verificar amanhã se ele chegou até o fim.

fjuniorr commented 1 year ago

Então provavelmente a coluna ft_despesa.id_unidade_orc para 2023 foi lida como valor lógico (ie. x.id_unidade_orc (logical)) porque o arquivo não tinha nenhuma linha, explicando o erro #193.

Agora levando em conta https://github.com/transparencia-mg/dtamg-py/issues/6 e o fato de que o join falhou é estranho que um erro não tenha sido pego antes do check da anonimização.

gabrielbdornas commented 1 year ago

Rotina rodou manualmente e até o fim em 11/04/2023.

Em 12/04/2023 CRON continuou não funcionando.

sudo grep CRON /var/log/syslog mostrou:

Apr 12 00:17:01 cge-pda CRON[8659]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 12 01:17:01 cge-pda CRON[8819]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 12 02:17:01 cge-pda CRON[8977]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 12 03:10:01 cge-pda CRON[9117]: (root) CMD (test -e /run/systemd/system || SERVICE_MODE=1 /sbin/e2scrub_all -A -r)
Apr 12 03:17:01 cge-pda CRON[9139]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 12 04:17:01 cge-pda CRON[9846]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 12 05:17:01 cge-pda CRON[10049]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 12 06:17:01 cge-pda CRON[10201]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 12 06:25:01 cge-pda CRON[10227]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.daily ))
Apr 12 07:17:01 cge-pda CRON[10866]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 12 08:04:01 cge-pda CRON[10988]: (root) CMD (   test -x /etc/cron.daily/popularity-contest && /etc/cron.daily/popularity-contest --crond)
Apr 12 08:17:01 cge-pda CRON[11027]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 12 09:17:01 cge-pda CRON[11178]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Apr 12 10:17:01 cge-pda CRON[11351]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)

Entendi que ele está tentando rodar o rotina mas não a está encontrando no usuário root. Incluí então o usuário gabriel.dornas no arquivo via comando contrab -e e modifiquei o timezone para tentar fazer a rotina rodar sem precisar esperar um dia:

SHELL=/bin/bash
CRON_TZ=GMT-3

50 10 * * * gabriel.dornas $HOME/age7/docker.sh > $HOME/age7/logs/cron.txt 2>&1

E então o log sudo grep CRON /var/log/syslog foi:

Apr 12 10:50:01 cge-pda CRON[11562]: (gabriel.dornas) CMD (gabriel.dornas $HOME/age7/docker.sh > $HOME/age7/logs/cron.txt 2>&1)
Apr 12 10:50:01 cge-pda CRON[11561]: (CRON) info (No MTA installed, discarding output)

O que poderia indicar o início do processo. Verificar até o final do dia mudanças no arquivo logs/all.txt. Também mudei o usuário do arquivo all.sh (sudo chown gabriel.dornas all.sh).

gabrielbdornas commented 1 year ago

Em 13/04/2023 eu clonei novamente o repositório age7 do github e o cronjob funcionou. Testar em 14/04/2023 se processo será iniciado corretamente, pois configurei o cronjob para rodar às 3 da manhã.

gabrielbdornas commented 1 year ago

Então provavelmente a coluna ft_despesa.id_unidade_orc para 2023 foi lida como valor lógico (ie. x.id_unidade_orc (logical)) porque o arquivo não tinha nenhuma linha, explicando o erro #193.

Agora levando em conta transparencia-mg/dtamg-py#6 e o fato de que o join falhou é estranho que um erro não tenha sido pego antes do check da anonimização.

@fjuniorr o arquivo all.sh não está executando a função extract_resource e sim a full_extract. Tentei procurar no histórico de issues porque tomamos esta decisão mas não encontrei.

De toda maneira o arquivo logs/full_extract.txt registra um WARNING quando alguma tabela vem sem nehum registro:

Ocorre que este arquivo, assim como outros dois da pasta logs foram incluídos no arquivo .gitignore:

Também tentei me lembrar o motivo desta escolha e ou procurar nos issues, mas não consegui. Você se lembra?

gabrielbdornas commented 1 year ago

Em 13/04/2023 eu clonei novamente o repositório age7 do github e o cronjob funcionou. Testar em 14/04/2023 se processo será iniciado corretamente, pois configurei o cronjob para rodar às 3 da manhã.

Cronjob funcionou mas processo não rodou. Erro:

fatal: could not read Username for 'https://github.com': No such device or add

Percebi que, por algum motivo, proxy não estava mais configurado no git git config --list. Configurei novamente e rodei o processo manualmente, mas não funcionou.

Segui então as orientações deste post e rodei o script manualmente mais uma vez, e ele rodou com sucesso. Conferir se tudo funcionará bem dia 18/04/2023.

fjuniorr commented 1 year ago

@fjuniorr o arquivo all.sh não está executando a função extract_resource e sim a full_extract. Tentei procurar no histórico de issues porque tomamos esta decisão mas não encontrei.

Esse não lembro

Também tentei me lembrar o motivo desta escolha e ou procurar nos issues, mas não consegui. Você se lembra?

Acho que era um receio de haver dados pessoais nos logs por causa dos relatórios de validações da frictionless.

gabrielbdornas commented 1 year ago

Processo rodou corretamente dia 18/04/2023. Apresentou lentidão para finalizar, mas atualizou conjuntos com sucesso.