`wait-for-it.sh` fails with Exit Code `127`

[bodo-hugo-barwich]

On master branch service api reports an Exit Code 127 with docker-compose up -d api:

$ docker-compose up -d api
Creating network "metacpan_traefik-network" with the default driver
Creating network "metacpan_default" with the default driver
Creating network "metacpan_web-network" with the default driver
Creating network "metacpan_elasticsearch" with the default driver
Creating network "metacpan_database" with the default driver
Creating network "metacpan_mongo" with the default driver
Creating metacpan_elasticsearch_1 ... done
Creating metacpan_pgdb_1          ... done
Creating metacpan_traefik_1       ... done
Creating metacpan_api_1           ... done
$ docker-compose ps
          Name                       Command                 State                  Ports           
----------------------------------------------------------------------------------------------------
metacpan_api_1             /metacpan-api/wait-for-es.     Exit 127                                  
                           ...                                                                      
metacpan_elasticsearch_1   /docker-entrypoint.sh elas     Up             0.0.0.0:49159->9200/tcp,:::
                           ...                                           49159->9200/tcp, 9300/tcp  
metacpan_pgdb_1            docker-entrypoint.sh           Up (healthy)   5432/tcp                   
                           postgres                                                                 
metacpan_traefik_1         /entrypoint.sh --api.insec     Up             0.0.0.0:80->80/tcp,:::80->8
                           ...                                           0/tcp, 0.0.0.0:8080->8080/t
                                                                         cp,:::8080->8080/tcp
$ docker-compose logs api
# [...]
api_1                     | + exec -- /metacpan-api/wait-for-it.sh -t 15 -s pgdb:5432 -- 'morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose' ./bin/api.pl
api_1                     | wait-for-it.sh: waiting 15 seconds for pgdb:5432
api_1                     | wait-for-it.sh: pgdb:5432 is available after 0 seconds
api_1                     | /metacpan-api/wait-for-it.sh: line 199: /metacpan-api/morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose: No such file or directory

The expected state should be:

$ docker-compose up -d api
Creating network "metacpan_traefik-network" with the default driver
Creating network "metacpan_default" with the default driver
Creating network "metacpan_web-network" with the default driver
Creating network "metacpan_elasticsearch" with the default driver
Creating network "metacpan_database" with the default driver
Creating network "metacpan_mongo" with the default driver
Creating metacpan_pgdb_1          ... done
Creating metacpan_elasticsearch_1 ... done
Creating metacpan_traefik_1       ... done
Creating metacpan_api_1           ... done
$ docker-compose ps
          Name                       Command                 State                  Ports           
----------------------------------------------------------------------------------------------------
metacpan_api_1             /metacpan-api/wait-for-es.     Up             0.0.0.0:5000->5000/tcp,:::5
                           ...                                           000->5000/tcp              
metacpan_elasticsearch_1   /docker-entrypoint.sh elas     Up             0.0.0.0:49160->9200/tcp,:::
                           ...                                           49160->9200/tcp, 9300/tcp  
metacpan_pgdb_1            docker-entrypoint.sh           Up (healthy)   5432/tcp                   
                           postgres                                                                 
metacpan_traefik_1         /entrypoint.sh --api.insec     Up             0.0.0.0:80->80/tcp,:::80->8
                           ...                                           0/tcp, 0.0.0.0:8080->8080/t
                                                                         cp,:::8080->8080/tcp  
$ docker-compose logs api
# [...]
api_1                     | + exec -- /metacpan-api/wait-for-it.sh -t 15 -s pgdb:5432 -- morbo -l 'http://*:5000' -w app.psgi -w bin -w lib -w templates --verbose ./bin/api.pl
api_1                     | wait-for-it.sh: waiting 15 seconds for pgdb:5432
api_1                     | wait-for-it.sh: pgdb:5432 is available after 0 seconds
api_1                     | Server available at http://127.0.0.1:5000

[bodo-hugo-barwich]

I built a docker-compose test environment with this GitHub Workflow docker-compose availability test and it reports that the components are built correctly: https://github.com/bodo-hugo-barwich/metacpan-docker/runs/5560173082?check_suite_focus=true#step:6:116

api_1                     | + exec -- /metacpan-api/wait-for-it.sh -t 15 -s pgdb:5432 -- morbo -l 'http://*:5000' -w app.psgi -w bin -w lib -w templates --verbose ./bin/api.pl
api_1                     | wait-for-it.sh: waiting 15 seconds for pgdb:5432
api_1                     | wait-for-it.sh: pgdb:5432 is available after 0 seconds
api_1                     | Server available at http://127.0.0.1:5000/
Component 'api' finished with:
 api_1 | Server available at http://127.0.0.1:5000/

but in my local development environment it keeps reporting me an execution error with "file not found":

api_1                     | + exec -- /metacpan-api/wait-for-it.sh -t 15 -s pgdb:5432 -- 'morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose' ./bin/api.pl
api_1                     | wait-for-it.sh: waiting 15 seconds for pgdb:5432
api_1                     | wait-for-it.sh: pgdb:5432 is available after 0 seconds
api_1                     | /metacpan-api/wait-for-it.sh: line 199: /metacpan-api/morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose: No such file or directory

[oalders]

@bodo-hugo-barwich is it possible that the file really doesn't exist locally? Maybe this is not running from the correct directory?

[bodo-hugo-barwich]

I see a difference between the command that succeeds:

api_1                     | + exec -- /metacpan-api/wait-for-it.sh -t 15 -s pgdb:5432 -- morbo -l 'http://*:5000' -w app.psgi -w bin -w lib -w templates --verbose ./bin/api.pl

and that one that fails:

api_1                     | + exec -- /metacpan-api/wait-for-it.sh -t 15 -s pgdb:5432 -- 'morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose' ./bin/api.pl

in where the quotes are set. This command is not defined in the wait-for-it.sh:

$ grep -n "" src/metacpan-api/wait-for-it.sh| sed -n 195,200p
195:    if [[ $RESULT -ne 0 && $STRICT -eq 1 ]]; then
196:        echoerr "$cmdname: strict mode, refusing to execute subprocess"
197:        exit $RESULT
198:    fi
199:    exec "${CLI[@]}"
200:else

So, this seems me to be the result of the api.command configuration in docker-compose.yml:

    command: >
      /metacpan-api/wait-for-es.sh http://elasticsearch:9200 "" --
      /metacpan-api/wait-for-it.sh -t 15 -s ${PGDB} --
      ${API_SERVER} ./bin/api.pl

I understand API_SERVER as an Environment Variable.

I also searched in the project where the "morbo" command is defined.

$ grep -ni "morbo" * -R |grep -vi distros
docker-compose.yml:216:    command: "/wait-for-it.sh mongodb:27017 -- morbo script/app.pl"
src/metacpan-api/bin/queue.pl:11:    ./bin/run morbo bin/api.pl
src/metacpan-api/bin/api.pl:11:    ./bin/run morbo bin/api.pl
src/metacpan-api/.env:2:API_SERVER=morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose
src/metacpan-api/improve-search-results/cpanfile.snapshot:173:      Mojo::Server::Morbo undef
src/metacpan-api/lib/MetaCPAN/API.pm:8:    ./bin/run morbo bin/api.pl
src/metacpan-api/cpanfile.snapshot:4402:      Mojo::Server::Morbo undef
src/metacpan-api/cpanfile.snapshot:4403:      Mojo::Server::Morbo::Backend undef
src/metacpan-api/cpanfile.snapshot:4404:      Mojo::Server::Morbo::Backend::Poll undef
grep: src/metacpan-cpan-extracted/.git/index: binary file matches
grep: src/metacpan-cpan-extracted-lite/.git/index: binary file matches

I see that API_SERVER is defined in the /.env file.

So, I changed src/metacpan-api/wait-for-it.sh:

$ git diff HEAD wait-for-it.sh
diff --git a/wait-for-it.sh b/wait-for-it.sh
index 33e0d0e0..dba9114e 100755
--- a/wait-for-it.sh
+++ b/wait-for-it.sh
@@ -196,6 +196,7 @@ if [[ $CLI != "" ]]; then
         echoerr "$cmdname: strict mode, refusing to execute subprocess"
         exit $RESULT
     fi
+    echo "cli cmd: '$CLI'"
     exec "${CLI[@]}"
 else
     exit $RESULT

Now the startup sequence shows:

$ docker-compose logs api
# [...]
api_1                     | + exec -- /metacpan-api/wait-for-it.sh -t 15 -s pgdb:5432 -- 'morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose' ./bin/api.pl
api_1                     | wait-for-it.sh: waiting 15 seconds for pgdb:5432
api_1                     | wait-for-it.sh: pgdb:5432 is available after 0 seconds
api_1                     | cli cmd: 'morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose'
api_1                     | /metacpan-api/wait-for-it.sh: line 202: /metacpan-api/morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose: No such file or directory

I also checked the changes in /.env with my development branch which still works:

$ git diff no-47_wrong-index .env
diff --git a/.env b/.env
index 074398d..8ea602e 100644
--- a/.env
+++ b/.env
@@ -1,4 +1,4 @@
 COMPOSE_PROJECT_NAME=metacpan
 PLACK_ENV=development
 PGDB=pgdb:5432
-API_SERVER=morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose
+API_SERVER="morbo -l http://*:5000 -w app.psgi -w bin -w lib -w templates --verbose"

To check whether the quotes would really make such a difference I imported the /.env file from my development branch:

$ git checkout no-47_wrong-index .env
Actualizada 1 ruta para 0c8a442

Relaunching the api component the logs document now:

$ docker-compose logs api
# [...]
api_1                     | + exec -- /metacpan-api/wait-for-it.sh -t 15 -s pgdb:5432 -- morbo -l 'http://*:5000' -w app.psgi -w bin -w lib -w templates --verbose ./bin/api.pl
api_1                     | wait-for-it.sh: waiting 15 seconds for pgdb:5432
api_1                     | wait-for-it.sh: pgdb:5432 is available after 0 seconds
api_1                     | cli cmd: 'morbo'
api_1                     | Server available at http://127.0.0.1:5000

[bodo-hugo-barwich]

Were the quotes in the /.env file to fix a different issue ?

[bodo-hugo-barwich]

According to the latest Automated Tests in GitHub the components are now up and operative: Automated Component Operativity Test

          Name                        Command                  State                                         Ports                                   
-----------------------------------------------------------------------------------------------------------------------------------------------------
metacpan_api_1             /metacpan-api/wait-for-es. ...   Up             0.0.0.0:5000->5000/tcp,:::5000->5000/tcp                                  
metacpan_elasticsearch_1   /docker-entrypoint.sh elas ...   Up             0.0.0.0:49153->9200/tcp,:::49153->9200/tcp, 9300/tcp                      
metacpan_pgdb_1            docker-entrypoint.sh postgres    Up (healthy)   5432/tcp                                                                  
metacpan_traefik_1         /entrypoint.sh --api.insec ...   Up             0.0.0.0:80->80/tcp,:::80->80/tcp, 0.0.0.0:8080->8080/tcp,:::8080->8080/tcp
Container Status Up:
Name|State
metacpan_api_1|Up
metacpan_elasticsearch_1|Up
metacpan_pgdb_1|Up (healthy)
metacpan_traefik_1|Up
Component 'api' Logs:
Attaching to metacpan_api_1

Automated Test Component api operative

Component 'api' finished with:
 api_1 | Server available at http://127.0.0.1:5000/

@oalders are you interested in keeping this test for the project since it is more conclusive than the existing docker-compose up test ? Or extending the docker-compose up test ?

[oalders]

@oalders are you interested in keeping this test for the project

Yes @bodo-hugo-barwich, that looks to be quite helpful.