Project

General

Profile

Download (82.8 KB)

Bug #17175 » arvados-failed.log

Lucas Di Pentima, 12/01/2020 09:46 PM

 
{"PID":16970,"command":"[git diff --shortstat]","dir":".","level":"info","msg":"executing","time":"2020-11-05T17:29:57.027654808-03:00"}
{"PID":16970,"command":"[git log -n1 --format=%H]","dir":".","level":"info","msg":"executing","time":"2020-11-05T17:30:01.577190232-03:00"}
{"PID":16970,"command":"[go install -ldflags -X git.arvados.org/arvados.git/lib/cmd.version=077e8c70a8f541ae85cb98805ca6f48a693dd767 -X main.version=077e8c70a8f541ae85cb98805ca6f48a693dd767]","dir":"/media/psf/arvados/cmd/arvados-server","level":"info","msg":"executing","time":"2020-11-05T17:30:01.627119047-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"certificates","time":"2020-11-05T17:30:08.050917972-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"keepproxy","time":"2020-11-05T17:30:08.050948377-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"seedDatabase","time":"2020-11-05T17:30:08.051050249-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"postgresql","time":"2020-11-05T17:30:08.057447044-03:00"}
{"PID":16970,"command":"[go install -ldflags -X git.arvados.org/arvados.git/lib/cmd.version=077e8c70a8f541ae85cb98805ca6f48a693dd767 -X main.version=077e8c70a8f541ae85cb98805ca6f48a693dd767]","dir":"/media/psf/arvados/services/keepproxy","level":"info","msg":"executing","time":"2020-11-05T17:30:08.056727410-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"certificates","time":"2020-11-05T17:30:08.050971149-03:00"}
{"PID":16970,"command":"[openssl genrsa -out rootCA.key 4096]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:08.057969690-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"postgresql","time":"2020-11-05T17:30:08.050975488-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"certificates","time":"2020-11-05T17:30:08.058326593-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"nginx","time":"2020-11-05T17:30:08.050979342-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"controller","time":"2020-11-05T17:30:08.050983164-03:00"}
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/arvados-server -version]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:08.059060138-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"certificates","time":"2020-11-05T17:30:08.059221815-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"arv-git-httpd","time":"2020-11-05T17:30:08.050987194-03:00"}
{"PID":16970,"command":"[go install -ldflags -X git.arvados.org/arvados.git/lib/cmd.version=077e8c70a8f541ae85cb98805ca6f48a693dd767 -X main.version=077e8c70a8f541ae85cb98805ca6f48a693dd767]","dir":"/media/psf/arvados/services/arv-git-httpd","level":"info","msg":"executing","time":"2020-11-05T17:30:08.059899743-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"health","time":"2020-11-05T17:30:08.050991058-03:00"}
{"PID":16970,"command":"[go install -ldflags -X git.arvados.org/arvados.git/lib/cmd.version=077e8c70a8f541ae85cb98805ca6f48a693dd767 -X main.version=077e8c70a8f541ae85cb98805ca6f48a693dd767]","dir":"/media/psf/arvados/services/health","level":"info","msg":"executing","time":"2020-11-05T17:30:08.060396070-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"installPassenger:services/api","time":"2020-11-05T17:30:08.051001023-03:00"}
{"PID":16970,"command":"[gem list --details bundler]","dir":"services/api","level":"info","msg":"executing","time":"2020-11-05T17:30:08.060896638-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"keepstore","time":"2020-11-05T17:30:08.051009806-03:00"}
{"PID":16970,"command":"[go install -ldflags -X git.arvados.org/arvados.git/lib/cmd.version=077e8c70a8f541ae85cb98805ca6f48a693dd767 -X main.version=077e8c70a8f541ae85cb98805ca6f48a693dd767]","dir":"/media/psf/arvados/services/keepstore","level":"info","msg":"executing","time":"2020-11-05T17:30:08.061752577-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"keep-web","time":"2020-11-05T17:30:08.051013828-03:00"}
{"PID":16970,"command":"[go install -ldflags -X git.arvados.org/arvados.git/lib/cmd.version=077e8c70a8f541ae85cb98805ca6f48a693dd767 -X main.version=077e8c70a8f541ae85cb98805ca6f48a693dd767]","dir":"/media/psf/arvados/services/keep-web","level":"info","msg":"executing","time":"2020-11-05T17:30:08.062259029-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"ws","time":"2020-11-05T17:30:08.051018014-03:00"}
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/arvados-server -version]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:08.062771416-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"installPassenger:apps/workbench","time":"2020-11-05T17:30:08.051027671-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"installPassenger:services/api","time":"2020-11-05T17:30:08.063035683-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"runPassenger:services/api","time":"2020-11-05T17:30:08.051031481-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"certificates","time":"2020-11-05T17:30:08.063158716-03:00"}
{"PID":16970,"level":"info","msg":"starting","task":"runPassenger:apps/workbench","time":"2020-11-05T17:30:08.051040808-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"installPassenger:apps/workbench","time":"2020-11-05T17:30:08.063296541-03:00"}
[openssl] Generating RSA private key, 4096 bit long modulus (2 primes)
[openssl] ..[arvados-server] /tmp/arvados-server-boot-420120283/bin/arvados-server 077e8c70a8f541ae85cb98805ca6f48a693dd767 (go1.14)
{"PID":16970,"level":"info","msg":"waiting","task":"postgresql","time":"2020-11-05T17:30:08.096089640-03:00"}
..[arvados-server] /tmp/arvados-server-boot-420120283/bin/arvados-server 077e8c70a8f541ae85cb98805ca6f48a693dd767 (go1.14)
{"PID":16970,"level":"info","msg":"waiting","task":"postgresql","time":"2020-11-05T17:30:08.179014019-03:00"}
........................................................................++++
[openssl] ...{"PID":16970,"command":"[bundle install --jobs 4 --path /root/.gem]","dir":"services/api","level":"info","msg":"executing","time":"2020-11-05T17:30:10.281369319-03:00"}
................++++
[openssl] e is 65537 (0x010001)
{"PID":16970,"command":"[openssl req -x509 -new -nodes -key rootCA.key -sha256 -days 3650 -out rootCA.crt -subj /C=US/ST=MA/O=Example Org/CN=localhost]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:10.633065374-03:00"}
{"PID":16970,"command":"[openssl genrsa -out server.key 2048]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:10.698585748-03:00"}
[openssl] Generating RSA private key, 2048 bit long modulus (2 primes)
[openssl] ......................................+++++
[openssl] ..................................................[services/api: bundle] Don't run Bundler as root. Bundler can ask for sudo if it is needed, and installing your bundle as root will break this application for all non-root users on this machine.
..........+++++
[openssl] e is 65537 (0x010001)
{"PID":16970,"command":"[openssl req -new -sha256 -key server.key -subj /C=US/ST=MA/O=Example Org/CN=localhost -reqexts SAN -config server.cfg -out server.csr]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:11.228777557-03:00"}
{"PID":16970,"command":"[openssl x509 -req -in server.csr -CA rootCA.crt -CAkey rootCA.key -CAcreateserial -out server.crt -extfile server.cfg -extensions SAN -days 3650 -sha256]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:11.273594854-03:00"}
[openssl] Signature ok
[openssl] subject=C = US, ST = MA, O = Example Org, CN = localhost
[openssl] Getting CA Private Key
{"PID":16970,"level":"info","msg":"ready","task":"certificates","time":"2020-11-05T17:30:11.341592002-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"postgresql","time":"2020-11-05T17:30:11.341808604-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"certificates","time":"2020-11-05T17:30:11.341693902-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"certificates","time":"2020-11-05T17:30:11.341697385-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"postgresql","time":"2020-11-05T17:30:11.342239082-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"certificates","time":"2020-11-05T17:30:11.341706276-03:00"}
{"PID":16970,"command":"[pg_config --bindir]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:11.342483811-03:00"}
{"PID":16970,"command":"[nginx -g error_log stderr info; -g pid /tmp/arvados-server-boot-420120283/nginx.pid; -c /tmp/arvados-server-boot-420120283/nginx.conf]","dir":".","level":"info","msg":"executing","time":"2020-11-05T17:30:11.343755787-03:00"}
{"PID":16970,"command":"[setuidgid postgres /usr/lib/postgresql/11/bin/initdb -D /tmp/arvados-server-boot-420120283/pgdata -E utf8]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:11.384329614-03:00"}
[-D] The files belonging to this database system will be owned by user "postgres".
[-D] This user must also own the server process.
[-D]
[-D] The database cluster will be initialized with locale "en_US.UTF-8".
[-D] The default text search configuration will be set to "english".
[-D]
[-D] Data page checksums are disabled.
[-D]
[-D] fixing permissions on existing directory /tmp/arvados-server-boot-420120283/pgdata ... ok
[-D] creating subdirectories ... ok
[-D] selecting default max_connections ... 100
[-D] selecting default shared_buffers ... 128MB
[-D] selecting default timezone ... [services/api: bundle] Using rake 13.0.1
[services/api: bundle] Using concurrent-ruby 1.1.6
[services/api: bundle] Using i18n 0.9.5
[services/api: bundle] Using minitest 5.10.3
[services/api: bundle] Using thread_safe 0.3.6
[services/api: bundle] Using tzinfo 1.2.7
[services/api: bundle] Using activesupport 5.2.4.3
[services/api: bundle] Using builder 3.2.4
[services/api: bundle] Using erubi 1.9.0
[services/api: bundle] Using mini_portile2 2.4.0
[services/api: bundle] Using nokogiri 1.10.10
[services/api: bundle] Using rails-dom-testing 2.0.3
[services/api: bundle] Using crass 1.0.6
[services/api: bundle] Using loofah 2.6.0
[services/api: bundle] Using rails-html-sanitizer 1.3.0
[services/api: bundle] Using actionview 5.2.4.3
[services/api: bundle] Using rack 2.2.3
[services/api: bundle] Using rack-test 1.1.0
[services/api: bundle] Using actionpack 5.2.4.3
[services/api: bundle] Using nio4r 2.5.2
[services/api: bundle] Using websocket-extensions 0.1.5
[services/api: bundle] Using websocket-driver 0.7.3
[services/api: bundle] Using actioncable 5.2.4.3
[services/api: bundle] Using globalid 0.4.2
[services/api: bundle] Using activejob 5.2.4.3
[services/api: bundle] Using mini_mime 1.0.2
[services/api: bundle] Using mail 2.7.1
[services/api: bundle] Using actionmailer 5.2.4.3
[services/api: bundle] Using activemodel 5.2.4.3
[services/api: bundle] Using arel 9.0.0
[services/api: bundle] Using activerecord 5.2.4.3
[services/api: bundle] Using mimemagic 0.3.5
[services/api: bundle] Using marcel 0.3.3
[services/api: bundle] Using activestorage 5.2.4.3
[services/api: bundle] Using acts_as_api 1.0.1
[services/api: bundle] Using public_suffix 4.0.3
[services/api: bundle] Using addressable 2.7.0
[services/api: bundle] Using andand 1.3.3
[services/api: bundle] Using extlib 0.9.16
[services/api: bundle] Using multi_json 1.14.1
[services/api: bundle] Using autoparse 0.3.3
[services/api: bundle] Using multipart-post 2.1.1
[services/api: bundle] Using faraday 0.15.4
[services/api: bundle] Using jwt 1.5.6
[services/api: bundle] Using memoist 0.16.2
[services/api: bundle] Using os 1.0.1
[services/api: bundle] Using signet 0.11.0
[services/api: bundle] Using googleauth 0.9.0
[services/api: bundle] Using launchy 2.4.3
[services/api: bundle] Using retriable 1.4.1
[services/api: bundle] Using arvados-google-api-client 0.8.7.4
[services/api: bundle] Using json 2.3.0
[services/api: bundle] Using arvados 1.5.0.pre20200114202620 from https://github.com/arvados/arvados.git (at /media/psf/arvados/services/api/vendor/cache/arvados-81725af5d5d2@81725af)
[services/api: bundle] Using msgpack 1.3.3
[services/api: bundle] Using bootsnap 1.4.7
[services/api: bundle] Using bundler 1.17.3
[services/api: bundle] Using byebug 11.0.1
[services/api: bundle] Using highline 2.0.1
[services/api: bundle] Using net-ssh 5.2.0
[services/api: bundle] Using net-scp 2.0.0
[services/api: bundle] Using net-sftp 2.1.2
[services/api: bundle] Using net-ssh-gateway 2.0.0
[services/api: bundle] Using capistrano 2.15.9
[services/api: bundle] Using execjs 2.7.0
[services/api: bundle] Using factory_bot 5.0.2
[services/api: bundle] Using method_source 1.0.0
[services/api: bundle] Using thor 1.0.1
[services/api: bundle] Using railties 5.2.4.3
[services/api: bundle] Using factory_bot_rails 5.0.1
[services/api: bundle] Using ffi 1.9.25
[services/api: bundle] Using hashie 3.6.0
[services/api: bundle] Using httpclient 2.8.3
[services/api: bundle] Using jquery-rails 4.3.3
[services/api: bundle] Using libv8 3.16.14.19 (x86_64-linux)
[services/api: bundle] Using rb-fsevent 0.10.3
[services/api: bundle] Using rb-inotify 0.9.10
[services/api: bundle] Using listen 3.2.1
[services/api: bundle] Using request_store 1.4.1
[services/api: bundle] Using lograge 0.10.0
[services/api: bundle] Using logstash-event 1.2.02
[services/api: bundle] Using metaclass 0.0.4
[services/api: bundle] Using mocha 1.8.0
[services/api: bundle] Using multi_xml 0.6.0
[services/api: bundle] Using oauth2 1.4.1
[services/api: bundle] Using oj 3.9.2
[services/api: bundle] Using omniauth 1.4.3
[services/api: bundle] Using omniauth-oauth2 1.5.0
[services/api: bundle] Using optimist 3.0.0
[services/api: bundle] Using passenger 6.0.2
[services/api: bundle] Using pg 1.1.4
[services/api: bundle] Using power_assert 1.1.4
[services/api: bundle] Using sprockets 3.7.2
[services/api: bundle] Using sprockets-rails 3.2.1
[services/api: bundle] Using rails 5.2.4.3
[services/api: bundle] Using rails-controller-testing 1.0.4
[services/api: bundle] Using rails-observers 0.1.5
[services/api: bundle] Using rails-perftest 0.0.7
[services/api: bundle] Using ref 2.0.0
[services/api: bundle] Using responders 2.4.1
[services/api: bundle] Using ruby-prof 0.15.9
[services/api: bundle] Using rvm-capistrano 1.5.6
[services/api: bundle] Using safe_yaml 1.0.5
[services/api: bundle] Using sass-listen 4.0.0
[services/api: bundle] Using sass 3.5.5
[services/api: bundle] Using tilt 2.0.8
[services/api: bundle] Using sass-rails 5.0.7
[services/api: bundle] Using simplecov-html 0.7.1
[services/api: bundle] Using simplecov 0.7.1
[services/api: bundle] Using simplecov-rcov 0.2.3
[services/api: bundle] Using sshkey 2.0.0
[services/api: bundle] Using test-unit 3.3.1
[services/api: bundle] Using themes_for_rails 0.5.1 from https://github.com/arvados/themes_for_rails (at /media/psf/arvados/services/api/vendor/cache/themes_for_rails-ddf6e592b3b6@ddf6e59)
[services/api: bundle] Using therubyracer 0.12.3
[services/api: bundle] Using uglifier 2.7.2
America/Cordoba
[-D] selecting dynamic shared memory implementation ... posix
[-D] creating configuration files ... ok
[-D] running bootstrap script ... [services/api: bundle] Updating files in vendor/cache
ok
[-D] performing post-bootstrap initialization ... {"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/keepproxy -version]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:12.989625261-03:00"}
[keepproxy] keepproxy 077e8c70a8f541ae85cb98805ca6f48a693dd767
{"PID":16970,"level":"info","msg":"waiting","task":"runPassenger:services/api","time":"2020-11-05T17:30:13.029875106-03:00"}
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/arv-git-httpd -version]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:13.102253408-03:00"}
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/health -version]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:13.103330218-03:00"}
[health] /tmp/arvados-server-boot-420120283/bin/health 077e8c70a8f541ae85cb98805ca6f48a693dd767 (go1.14)
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/health]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:13.118002864-03:00"}
[arv-git-httpd] arv-git-httpd 077e8c70a8f541ae85cb98805ca6f48a693dd767
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/arv-git-httpd]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:13.118821995-03:00"}
[arv-git-httpd] {"level":"info","msg":"arv-git-httpd 077e8c70a8f541ae85cb98805ca6f48a693dd767 started","time":"2020-11-05T17:30:13.163768361-03:00"}
[arv-git-httpd] {"level":"info","msg":"Listening at 127.0.0.1:37225","time":"2020-11-05T17:30:13.163807839-03:00"}
[arv-git-httpd] {"level":"info","msg":"Repository root /var/lib/arvados/git/repositories","time":"2020-11-05T17:30:13.163814735-03:00"}
[health] {"Listen":"127.0.0.1:36337","PID":17304,"Service":"arvados-health","URL":"http://localhost:36337/","level":"info","msg":"listening","time":"2020-11-05T17:30:13.174542815-03:00"}
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/keep-web -version]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:13.588765316-03:00"}
[keep-web] keep-web 077e8c70a8f541ae85cb98805ca6f48a693dd767
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/keep-web]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:13.624826905-03:00"}
[keep-web] {"level":"info","msg":"keep-web 077e8c70a8f541ae85cb98805ca6f48a693dd767 started","time":"2020-11-05T17:30:13.662763844-03:00"}
[keep-web] {"level":"info","msg":"Listening at 127.0.0.1:32871","time":"2020-11-05T17:30:13.679582238-03:00"}
ok
[-D] syncing data to disk ... {"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/keepstore -version]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:14.282407250-03:00"}

[-D] WARNING: enabling "trust" authentication for local connections
[-D] You can change this by editing pg_hba.conf or using the option -A, or
[-D] --auth-local and --auth-host, the next time you run initdb.
[-D] ok
[-D]
[-D] Success. You can now start the database server using:
[-D]
[-D] /usr/lib/postgresql/11/bin/pg_ctl -D /tmp/arvados-server-boot-420120283/pgdata -l logfile start
[-D]
{"PID":16970,"command":"[cp server.crt server.key /tmp/arvados-server-boot-420120283/pgdata]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:14.293653775-03:00"}
[keepstore] /tmp/arvados-server-boot-420120283/bin/keepstore 077e8c70a8f541ae85cb98805ca6f48a693dd767 (go1.14)
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/keepstore]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:14.294372669-03:00"}
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/keepstore]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:14.294689304-03:00"}
{"PID":16970,"command":"[chown postgres /tmp/arvados-server-boot-420120283/pgdata/server.crt /tmp/arvados-server-boot-420120283/pgdata/server.key]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:14.296671637-03:00"}
{"PID":16970,"command":"[setuidgid postgres /usr/lib/postgresql/11/bin/postgres -l -D /tmp/arvados-server-boot-420120283/pgdata -k /tmp/arvados-server-boot-420120283/pgdata -p 44031]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:14.303158718-03:00"}
[keepstore] {"PID":17333,"level":"info","msg":"keepstore 077e8c70a8f541ae85cb98805ca6f48a693dd767 starting, pid 17333","time":"2020-11-05T17:30:14.332316751-03:00"}
[keepstore] {"PID":17334,"level":"info","msg":"keepstore 077e8c70a8f541ae85cb98805ca6f48a693dd767 starting, pid 17334","time":"2020-11-05T17:30:14.334198102-03:00"}
[keepstore] {"PID":17334,"level":"info","msg":"started volume zzzzz-nyw5e-000000000000000 ([UnixVolume /tmp/arvados-server-boot-420120283/keep0.data]), ReadOnly=false","time":"2020-11-05T17:30:14.341364808-03:00"}
[-l] 2020-11-05 17:30:14.343 -03 [17350] LOG: listening on IPv6 address "::1", port 44031
[-l] 2020-11-05 17:30:14.343 -03 [17350] LOG: listening on IPv4 address "127.0.0.1", port 44031
[-l] 2020-11-05 17:30:14.345 -03 [17350] LOG: listening on Unix socket "/tmp/arvados-server-boot-420120283/pgdata/.s.PGSQL.44031"
[keepstore] {"PID":17333,"level":"info","msg":"started volume zzzzz-nyw5e-000000000000001 ([UnixVolume /tmp/arvados-server-boot-420120283/keep1.data]), ReadOnly=false","time":"2020-11-05T17:30:14.348134185-03:00"}
[keepstore] {"Listen":"127.0.0.1:38899","PID":17334,"Service":"keepstore","URL":"http://localhost:38899/","level":"info","msg":"listening","time":"2020-11-05T17:30:14.349655053-03:00"}
[keepstore] {"Listen":"127.0.0.1:46137","PID":17333,"Service":"keepstore","URL":"http://localhost:46137/","level":"info","msg":"listening","time":"2020-11-05T17:30:14.355126160-03:00"}
[-l] 2020-11-05 17:30:14.367 -03 [17355] LOG: database system was shut down at 2020-11-05 17:30:14 -03
[-l] 2020-11-05 17:30:14.371 -03 [17350] LOG: database system is ready to accept connections
[-l] 2020-11-05 17:30:14.376 -03 [17356] FATAL: the database system is starting up
[-l] 2020-11-05 17:30:14.378 -03 [17363] FATAL: role "root" does not exist
{"PID":16970,"level":"info","msg":"ready","task":"postgresql","time":"2020-11-05T17:30:14.622653666-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"installPassenger:services/api","time":"2020-11-05T17:30:14.624275078-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"postgresql","time":"2020-11-05T17:30:14.622707432-03:00"}
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/arvados-server controller -config /tmp/arvados-server-boot-420120283/config.yml]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:14.624453567-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"postgresql","time":"2020-11-05T17:30:14.622689100-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"installPassenger:services/api","time":"2020-11-05T17:30:14.624710881-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"postgresql","time":"2020-11-05T17:30:14.622698525-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"postgresql","time":"2020-11-05T17:30:14.622699936-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"nginx","time":"2020-11-05T17:30:14.625271648-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"nginx","time":"2020-11-05T17:30:14.625490666-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"controller","time":"2020-11-05T17:30:14.625604717-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"controller","time":"2020-11-05T17:30:14.625839183-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"arv-git-httpd","time":"2020-11-05T17:30:14.625875460-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"arv-git-httpd","time":"2020-11-05T17:30:14.626009307-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"health","time":"2020-11-05T17:30:14.626135387-03:00"}
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/arvados-server ws -config /tmp/arvados-server-boot-420120283/config.yml]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:14.625087294-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"health","time":"2020-11-05T17:30:14.626324628-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"keepproxy","time":"2020-11-05T17:30:14.626872527-03:00"}
[controller] {"Listen":"127.0.0.1:38437","PID":17365,"Service":"arvados-controller","URL":"http://localhost:38437/","level":"info","msg":"listening","time":"2020-11-05T17:30:14.684494616-03:00"}
[ws] {"Listen":"127.0.0.1:33185","PID":17366,"Service":"arvados-ws","URL":"http://localhost:33185/","level":"info","msg":"listening","time":"2020-11-05T17:30:14.693921421-03:00"}
[services/api: bundle] Bundle complete! 37 Gemfile dependencies, 114 gems now installed.
[services/api: bundle] Bundled gems are installed into `/root/.gem`
{"PID":16970,"command":"[bundle exec passenger-config build-native-support]","dir":"services/api","level":"info","msg":"executing","time":"2020-11-05T17:30:16.163907666-03:00"}
{"PID":16970,"command":"[bundle exec passenger-config install-standalone-runtime]","dir":"services/api","level":"info","msg":"executing","time":"2020-11-05T17:30:16.456894979-03:00"}
[services/api: passenger-config] The Phusion Passenger Standalone runtime is already installed.
[services/api: passenger-config] If you want to redownload it, re-run this program with the --force parameter.
{"PID":16970,"command":"[bundle exec passenger-config validate-install]","dir":"services/api","level":"info","msg":"executing","time":"2020-11-05T17:30:16.779542200-03:00"}
[services/api: passenger-config] * Checking whether this Passenger install is in PATH... ✓
[services/api: passenger-config] * Checking whether there are no other Passenger installations... ✓
[services/api: passenger-config]
[services/api: passenger-config] Everything looks good. :-)
{"PID":16970,"level":"info","msg":"ready","task":"installPassenger:services/api","time":"2020-11-05T17:30:17.253288711-03:00"}
{"PID":16970,"command":"[gem list --details bundler]","dir":"apps/workbench","level":"info","msg":"executing","time":"2020-11-05T17:30:17.253897623-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"installPassenger:services/api","time":"2020-11-05T17:30:17.253315765-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"runPassenger:services/api","time":"2020-11-05T17:30:17.254685697-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"installPassenger:services/api","time":"2020-11-05T17:30:17.253326664-03:00"}
{"PID":16970,"command":"[bundle exec rake db:setup]","dir":"services/api","level":"info","msg":"executing","time":"2020-11-05T17:30:17.254968154-03:00"}
{"PID":16970,"command":"[/tmp/arvados-server-boot-420120283/bin/keepproxy]","dir":"/tmp/arvados-server-boot-420120283","level":"info","msg":"executing","time":"2020-11-05T17:30:17.254979948-03:00"}
{"PID":16970,"command":"[bundle exec passenger start -p 36571 --log-file /dev/stderr --log-level 4 --no-friendly-error-pages --pid-file /tmp/arvados-server-boot-420120283/passenger.services_api.pid]","dir":"services/api","level":"info","msg":"executing","time":"2020-11-05T17:30:17.254879090-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"keepproxy","time":"2020-11-05T17:30:17.254909724-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"keepstore","time":"2020-11-05T17:30:17.256524040-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"keepstore","time":"2020-11-05T17:30:17.256693993-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"keep-web","time":"2020-11-05T17:30:17.256836502-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"keep-web","time":"2020-11-05T17:30:17.256937287-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"ws","time":"2020-11-05T17:30:17.257058414-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"ws","time":"2020-11-05T17:30:17.257171441-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"installPassenger:services/api","time":"2020-11-05T17:30:17.257281687-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"installPassenger:services/api","time":"2020-11-05T17:30:17.257387801-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"runPassenger:services/api","time":"2020-11-05T17:30:17.257719426-03:00"}
{"PID":16970,"level":"info","msg":"ready","task":"runPassenger:services/api","time":"2020-11-05T17:30:17.257840414-03:00"}
{"PID":16970,"level":"info","msg":"waiting","task":"installPassenger:apps/workbench","time":"2020-11-05T17:30:17.257945421-03:00"}
[keepproxy] time="2020-11-05T17:30:17-03:00" level=info msg="keepproxy 077e8c70a8f541ae85cb98805ca6f48a693dd767 started"
[controller] {"PID":17365,"RequestID":"req-1faj24x7ujqu81qpblhx","level":"info","msg":"request","remoteAddr":"127.0.0.1:33790","reqBytes":0,"reqForwardedFor":"127.0.0.1","reqHost":"localhost:40157","reqMethod":"GET","reqPath":"discovery/v1/apis/arvados/v1/rest","reqQuery":"","time":"2020-11-05T17:30:17.282161468-03:00"}
[controller] {"PID":17365,"RequestID":"req-1faj24x7ujqu81qpblhx","level":"info","msg":"response","remoteAddr":"127.0.0.1:33790","reqBytes":0,"reqForwardedFor":"127.0.0.1","reqHost":"localhost:40157","reqMethod":"GET","reqPath":"discovery/v1/apis/arvados/v1/rest","reqQuery":"","respBody":"{\"errors\":[\"Get \\\"http://localhost:36571/discovery/v1/apis/arvados/v1/rest\\\": dial tcp [::1]:36571: connect: connection refused\"]}\n","respBytes":131,"respStatus":"Bad Gateway","respStatusCode":502,"time":"2020-11-05T17:30:17.282633738-03:00","timeToStatus":0.000448,"timeTotal":0.000470,"timeWriteBody":0.000022}
{"PID":16970,"command":"[bundle install --jobs 4 --path /root/.gem]","dir":"apps/workbench","level":"info","msg":"executing","time":"2020-11-05T17:30:17.722788425-03:00"}
[apps/workbench: bundle] Don't run Bundler as root. Bundler can ask for sudo if it is needed, and installing your bundle as root will break this application for all non-root users on this machine.
[services/api: passenger] [ N 2020-11-05 17:30:18.1575 17418/T1 age/Wat/WatchdogMain.cpp:1366 ]: Starting Passenger watchdog...
[services/api: passenger] [ W 2020-11-05 17:30:18.1602 17418/T1 age/Wat/WatchdogMain.cpp:1079 ]: WARNING: potential privilege escalation vulnerability detected. Phusion Passenger is running as root, and part(s) of the Passenger instance directory (/tmp/arvados-server-boot-420120283) can be changed by non-root user(s):
[services/api: passenger]
[services/api: passenger] - /tmp/arvados-server-boot-420120283 is not secure: it can be modified by user nobody
[services/api: passenger]
[services/api: passenger] Please either fix up the permissions for the insecure paths, or use a different location for the instance dir that can only be modified by root.
[services/api: passenger] [ N 2020-11-05 17:30:18.1814 17421/T1 age/Cor/CoreMain.cpp:1339 ]: Starting Passenger core...
[services/api: passenger] [ N 2020-11-05 17:30:18.1816 17421/T1 age/Cor/CoreMain.cpp:256 ]: Passenger core running in multi-application mode.
[services/api: passenger] [ N 2020-11-05 17:30:18.1903 17421/T1 age/Cor/CoreMain.cpp:1014 ]: Passenger core online, PID 17421
[services/api: passenger] [ I 2020-11-05 17:30:18.1906 17418/T1 age/Wat/WatchdogMain.cpp:1412 ]: All Phusion Passenger agents started!
[services/api: passenger] =============== Phusion Passenger Standalone web server started ===============
[services/api: passenger] PID file: /tmp/arvados-server-boot-420120283/passenger.services_api.pid
[services/api: passenger] Log file: /dev/stderr
[services/api: passenger] Environment: test
[services/api: passenger] Accessible via: http://0.0.0.0:36571/
[services/api: passenger]
[services/api: passenger] You can stop Phusion Passenger Standalone by pressing Ctrl-C.
[services/api: passenger] Problems? Check https://www.phusionpassenger.com/library/admin/standalone/troubleshooting/
[services/api: passenger] ===============================================================================
[apps/workbench: bundle] Using rake 13.0.1
[apps/workbench: bundle] Using RedCloth 4.3.2
[apps/workbench: bundle] Using concurrent-ruby 1.1.6
[apps/workbench: bundle] Using i18n 0.9.5
[apps/workbench: bundle] Using minitest 5.10.3
[apps/workbench: bundle] Using thread_safe 0.3.6
[apps/workbench: bundle] Using tzinfo 1.2.7
[apps/workbench: bundle] Using activesupport 5.2.4.3
[apps/workbench: bundle] Using builder 3.2.4
[apps/workbench: bundle] Using erubi 1.9.0
[apps/workbench: bundle] Using mini_portile2 2.4.0
[apps/workbench: bundle] Using nokogiri 1.10.10
[apps/workbench: bundle] Using rails-dom-testing 2.0.3
[apps/workbench: bundle] Using crass 1.0.6
[apps/workbench: bundle] Using loofah 2.6.0
[apps/workbench: bundle] Using rails-html-sanitizer 1.3.0
[apps/workbench: bundle] Using actionview 5.2.4.3
[apps/workbench: bundle] Using rack 2.2.3
[apps/workbench: bundle] Using rack-test 1.1.0
[apps/workbench: bundle] Using actionpack 5.2.4.3
[apps/workbench: bundle] Using nio4r 2.5.2
[apps/workbench: bundle] Using websocket-extensions 0.1.5
[apps/workbench: bundle] Using websocket-driver 0.7.3
[apps/workbench: bundle] Using actioncable 5.2.4.3
[apps/workbench: bundle] Using globalid 0.4.2
[apps/workbench: bundle] Using activejob 5.2.4.3
[apps/workbench: bundle] Using mini_mime 1.0.2
[apps/workbench: bundle] Using mail 2.7.1
[apps/workbench: bundle] Using actionmailer 5.2.4.3
[apps/workbench: bundle] Using activemodel 5.2.4.3
[apps/workbench: bundle] Using arel 9.0.0
[apps/workbench: bundle] Using activerecord 5.2.4.3
[apps/workbench: bundle] Using activerecord-nulldb-adapter 0.3.9 from https://github.com/arvados/nulldb (at /media/psf/arvados/apps/workbench/vendor/cache/nulldb-d8e0073b665a@d8e0073)
[apps/workbench: bundle] Using mimemagic 0.3.5
[apps/workbench: bundle] Using marcel 0.3.3
[apps/workbench: bundle] Using activestorage 5.2.4.3
[apps/workbench: bundle] Using public_suffix 4.0.5
[apps/workbench: bundle] Using addressable 2.7.0
[apps/workbench: bundle] Using andand 1.3.3
[apps/workbench: bundle] Using angularjs-rails 1.3.15
[apps/workbench: bundle] Using extlib 0.9.16
[apps/workbench: bundle] Using multi_json 1.15.0
[apps/workbench: bundle] Using autoparse 0.3.3
[apps/workbench: bundle] Using multipart-post 2.1.1
[apps/workbench: bundle] Using faraday 0.15.4
[apps/workbench: bundle] Using jwt 1.5.6
[apps/workbench: bundle] Using memoist 0.16.2
[apps/workbench: bundle] Using os 1.1.1
[apps/workbench: bundle] Using signet 0.11.0
[apps/workbench: bundle] Using googleauth 0.9.0
[apps/workbench: bundle] Using launchy 2.4.3
[apps/workbench: bundle] Using retriable 1.4.1
[apps/workbench: bundle] Using arvados-google-api-client 0.8.7.4
[apps/workbench: bundle] Using json 2.3.0
[apps/workbench: bundle] Using arvados 1.5.0.pre20200114202620 from https://github.com/arvados/arvados.git (at /media/psf/arvados/apps/workbench/vendor/cache/arvados-c210114aa8c7@c210114)
[apps/workbench: bundle] Using execjs 2.7.0
[apps/workbench: bundle] Using autoprefixer-rails 9.5.1.1
[apps/workbench: bundle] Using msgpack 1.3.3
[apps/workbench: bundle] Using bootsnap 1.4.7
[apps/workbench: bundle] Using ffi 1.10.0
[apps/workbench: bundle] Using sassc 2.0.1
[apps/workbench: bundle] Using bootstrap-sass 3.4.1
[apps/workbench: bundle] Using method_source 1.0.0
[apps/workbench: bundle] Using thor 1.0.1
[apps/workbench: bundle] Using railties 5.2.4.3
[apps/workbench: bundle] Using bootstrap-tab-history-rails 0.1.0
[apps/workbench: bundle] Using bootstrap-x-editable-rails 1.5.1.1
[apps/workbench: bundle] Using bundler 1.17.3
[apps/workbench: bundle] Using byebug 11.0.1
[apps/workbench: bundle] Using highline 2.0.2
[apps/workbench: bundle] Using net-ssh 5.2.0
[apps/workbench: bundle] Using net-scp 2.0.0
[apps/workbench: bundle] Using net-sftp 2.1.2
[apps/workbench: bundle] Using net-ssh-gateway 2.0.0
[apps/workbench: bundle] Using capistrano 2.15.9
[apps/workbench: bundle] Using mime-types-data 3.2019.0331
[apps/workbench: bundle] Using mime-types 3.2.2
[apps/workbench: bundle] Using xpath 2.1.0
[apps/workbench: bundle] Using capybara 2.5.0
[apps/workbench: bundle] Using childprocess 0.9.0
[apps/workbench: bundle] Using cliver 0.3.2
[apps/workbench: bundle] Using coffee-script-source 1.12.2
[apps/workbench: bundle] Using coffee-script 2.4.1
[apps/workbench: bundle] Using coffee-rails 4.2.2
[apps/workbench: bundle] Using commonjs 0.2.7
[apps/workbench: bundle] Using deep_merge 1.2.1
[apps/workbench: bundle] Using docile 1.3.1
[apps/workbench: bundle] Using flamegraph 0.9.5
[apps/workbench: bundle] Using headless 1.0.2
[apps/workbench: bundle] Using httpclient 2.8.3
[apps/workbench: bundle] Using jquery-rails 4.3.3
[apps/workbench: bundle] Using less 2.6.0
[apps/workbench: bundle] Using sprockets 3.7.2
[apps/workbench: bundle] Using less-rails 4.0.0
[apps/workbench: bundle] Using libv8 3.16.14.19 (x86_64-linux)
[apps/workbench: bundle] Using request_store 1.4.1
[apps/workbench: bundle] Using lograge 0.10.0
[apps/workbench: bundle] Using logstash-event 1.2.02
[apps/workbench: bundle] Using metaclass 0.0.4
[apps/workbench: bundle] Using mocha 1.8.0
[apps/workbench: bundle] Using morrisjs-rails 0.5.1.2
[apps/workbench: bundle] Using sprockets-rails 3.2.1
[apps/workbench: bundle] Using rails 5.2.4.3
[apps/workbench: bundle] Using npm-rails 0.2.1
[apps/workbench: bundle] Using oj 3.7.12
[apps/workbench: bundle] Using passenger 6.0.2
[apps/workbench: bundle] Using piwik_analytics 1.0.2
[apps/workbench: bundle] Using poltergeist 1.5.1
[apps/workbench: bundle] Using rack-mini-profiler 1.0.2
[apps/workbench: bundle] Using rails-controller-testing 1.0.4
[apps/workbench: bundle] Using rails-perftest 0.0.7
[apps/workbench: bundle] Using raphael-rails 2.1.2
[apps/workbench: bundle] Using rb-fsevent 0.10.3
[apps/workbench: bundle] Using rb-inotify 0.10.0
[apps/workbench: bundle] Using ref 2.0.0
[apps/workbench: bundle] Using responders 2.4.1
[apps/workbench: bundle] Using ruby-debug-passenger 0.2.0
[apps/workbench: bundle] Using ruby-prof 0.17.0
[apps/workbench: bundle] Using rubyzip 1.3.0
[apps/workbench: bundle] Using rvm-capistrano 1.5.6
[apps/workbench: bundle] Using safe_yaml 1.0.5
[apps/workbench: bundle] Using sass-listen 4.0.0
[apps/workbench: bundle] Using sass 3.7.4
[apps/workbench: bundle] Using tilt 2.0.9
[apps/workbench: bundle] Using sassc-rails 2.1.0
[apps/workbench: bundle] Using selenium-webdriver 3.141.0
[apps/workbench: bundle] Using simplecov-html 0.10.2
[apps/workbench: bundle] Using simplecov 0.16.1
[apps/workbench: bundle] Using simplecov-rcov 0.2.3
[apps/workbench: bundle] Using sshkey 2.0.0
[apps/workbench: bundle] Using themes_for_rails 0.5.1 from https://github.com/arvados/themes_for_rails (at /media/psf/arvados/apps/workbench/vendor/cache/themes_for_rails-ddf6e592b3b6@ddf6e59)
[apps/workbench: bundle] Using therubyracer 0.12.3
[apps/workbench: bundle] Using uglifier 2.7.2
[apps/workbench: bundle] Updating files in vendor/cache
[controller] {"PID":17365,"RequestID":"req-19pv4u3aca0ytpktqd2p","level":"info","msg":"request","remoteAddr":"127.0.0.1:33808","reqBytes":0,"reqForwardedFor":"127.0.0.1","reqHost":"localhost:40157","reqMethod":"GET","reqPath":"discovery/v1/apis/arvados/v1/rest","reqQuery":"","time":"2020-11-05T17:30:19.286270860-03:00"}
[services/api: passenger] [ N 2020-11-05 17:30:21.4001 17421/T8 age/Cor/SecurityUpdateChecker.h:519 ]: Security update check: no update found (next check in 24 hours)
[-l] 2020-11-05 17:30:22.053 -03 [17526] ERROR: database "arvados_test" already exists
[-l] 2020-11-05 17:30:22.053 -03 [17526] STATEMENT: CREATE DATABASE "arvados_test" ENCODING = 'utf8' TEMPLATE = "template0" LC_COLLATE = 'en_US.UTF-8'
[services/api: rake] Database 'arvados_test' already exists
[services/api: rake]  (0.2ms) SET TIME ZONE 'UTC'
[services/api: rake]  (0.5ms) CREATE DATABASE "arvados_test" ENCODING = 'utf8' TEMPLATE = "template0" LC_COLLATE = 'en_US.UTF-8'
[services/api: rake]  (0.1ms) SET TIME ZONE 'UTC'
[services/api: rake] set_config
[services/api: rake] ------------
[services/api: rake]
[services/api: rake] (1 row)
[services/api: rake]
[services/api: passenger] App 17449 output:  (0.6ms) SELECT clock_timestamp() AT TIME ZONE 'UTC'
[services/api: passenger] [ I 2020-11-05 17:30:23.3943 17421/Tf age/Cor/Spa/SmartSpawner.h:463 ]: Preloader for /media/psf/arvados/services/api started on PID 17449, listening on unix:/tmp/arvados-server-boot-420120283/passenger.Ltkue6W/apps.s/preloader.1h6yr0l
[services/api: passenger] App 17550 output:  (0.1ms) SET TIME ZONE 'UTC'
[services/api: passenger] App 17550 output: User Load (1.2ms) SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."uuid" = $1 LIMIT $2 [["uuid", "zzzzz-tpzed-000000000000000"], ["LIMIT", 1]]
[services/api: passenger] App 17550 output: User Load (0.6ms) SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."uuid" = $1 ORDER BY "users"."id" ASC LIMIT $2 [["uuid", "zzzzz-tpzed-000000000000000"], ["LIMIT", 1]]
[services/api: passenger] App 17550 output:  (0.2ms) BEGIN
[services/api: passenger] App 17550 output:  (1.2ms) SELECT clock_timestamp() AT TIME ZONE 'UTC'
[services/api: passenger] App 17550 output:  (1.0ms) SELECT COUNT(*) FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."uuid" = $1 AND (email = 'root') AND "users"."is_admin" = $2 [["uuid", "zzzzz-tpzed-000000000000000"], ["is_admin", true]]
[services/api: passenger] App 17550 output:  (0.8ms) SELECT COUNT(*) FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."uuid" = $1 AND (uuid not like '%-000000000000000') AND "users"."is_admin" = $2 [["uuid", "zzzzz-tpzed-000000000000000"], ["is_admin", true]]
[services/api: passenger] App 17550 output: User Create (1.3ms) INSERT INTO "users" ("uuid", "owner_uuid", "created_at", "modified_by_user_uuid", "modified_at", "email", "first_name", "last_name", "is_admin", "updated_at", "is_active") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) RETURNING "id" [["uuid", "zzzzz-tpzed-000000000000000"], ["owner_uuid", "zzzzz-tpzed-000000000000000"], ["created_at", "2020-11-05 20:30:23.615071"], ["modified_by_user_uuid", "zzzzz-tpzed-000000000000000"], ["modified_at", "2020-11-05 20:30:23.617030"], ["email", "root"], ["first_name", "root"], ["last_name", ""], ["is_admin", true], ["updated_at", "2020-11-05 20:30:23.617030"], ["is_active", true]]
[services/api: passenger] App 17550 output:  (1.2ms) SELECT clock_timestamp() AT TIME ZONE 'UTC'
[services/api: passenger] App 17550 output: Log Create (2.0ms) INSERT INTO "logs" ("uuid", "owner_uuid", "modified_by_user_uuid", "object_uuid", "event_at", "event_type", "summary", "properties", "created_at", "updated_at", "modified_at", "object_owner_uuid") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12) RETURNING "id" [["uuid", "zzzzz-57u5n-0ohp5n08lcq9jdt"], ["owner_uuid", "zzzzz-tpzed-000000000000000"], ["modified_by_user_uuid", "zzzzz-tpzed-000000000000000"], ["object_uuid", "zzzzz-tpzed-000000000000000"], ["event_at", "2020-11-05 20:30:23.615071"], ["event_type", "create"], ["summary", "create of zzzzz-tpzed-000000000000000"], ["properties", "{\"old_etag\":null,\"old_attributes\":null,\"new_etag\":\"ufk7qujnf8ljvvn0trto01r4\",\"new_attributes\":{\"id\":1,\"uuid\":\"zzzzz-tpzed-000000000000000\",\"owner_uuid\":\"zzzzz-tpzed-000000000000000\",\"created_at\":\"2020-11-05T20:30:23.615071546Z\",\"modified_by_client_uuid\":null,\"modified_by_user_uuid\":\"zzzzz-tpzed-000000000000000\",\"modified_at\":\"2020-11-05T20:30:23.617030000Z\",\"email\":\"root\",\"first_name\":\"root\",\"last_name\":\"\",\"identity_url\":null,\"is_admin\":true,\"prefs\":{},\"updated_at\":\"2020-11-05T20:30:23.617030000Z\",\"default_owner_uuid\":null,\"is_active\":true,\"username\":null,\"redirect_to_user_uuid\":null}}"], ["created_at", "2020-11-05 20:30:23.685897"], ["updated_at", "2020-11-05 20:30:23.686467"], ["modified_at", "2020-11-05 20:30:23.686467"], ["object_owner_uuid", "zzzzz-tpzed-000000000000000"]]
[services/api: passenger] App 17550 output:  (0.8ms) NOTIFY logs, '1'
[services/api: passenger] App 17550 output:  (1.1ms) LOCK TABLE materialized_permissions in SHARE MODE
[services/api: passenger] App 17550 output: SQL (0.3ms) SET LOCAL enable_mergejoin to false;
[services/api: passenger] App 17550 output: update_permissions.select (14.2ms) 
[services/api: passenger] App 17550 output: create temporary table temp_perms_11405793009089601573 on commit drop
[services/api: passenger] App 17550 output: as select * from compute_permission_subgraph($1, $2, $3, $4)
[services/api: passenger] App 17550 output:  [[nil, "zzzzz-tpzed-000000000000000"], [nil, "zzzzz-tpzed-000000000000000"], [nil, 3], [nil, "zzzzz-tpzed-000000000000000"]]
[services/api: passenger] App 17550 output: SQL (0.3ms) SET LOCAL enable_mergejoin to true;
[services/api: passenger] App 17550 output: update_permissions.delete (1.0ms) 
[services/api: passenger] App 17550 output: delete from materialized_permissions where
[services/api: passenger] App 17550 output: target_uuid in (select target_uuid from temp_perms_11405793009089601573) and
[services/api: passenger] App 17550 output: not exists (select 1 from temp_perms_11405793009089601573
[services/api: passenger] App 17550 output: where target_uuid=materialized_permissions.target_uuid and
[services/api: passenger] App 17550 output: user_uuid=materialized_permissions.user_uuid and
[services/api: passenger] App 17550 output: val>0)
[services/api: passenger] App 17550 output: 
[services/api: passenger] App 17550 output: update_permissions.insert (0.6ms) 
[services/api: passenger] App 17550 output: insert into materialized_permissions (user_uuid, target_uuid, perm_level, traverse_owned)
[services/api: passenger] App 17550 output: select user_uuid, target_uuid, val as perm_level, traverse_owned from temp_perms_11405793009089601573 where val>0
[services/api: passenger] App 17550 output: on conflict (user_uuid, target_uuid) do update set perm_level=EXCLUDED.perm_level, traverse_owned=EXCLUDED.traverse_owned;
[services/api: passenger] App 17550 output: 
[services/api: passenger] App 17550 output: check_permissions_against_full_refresh.permission_table (0.7ms) 
[services/api: passenger] App 17550 output: select user_uuid, target_uuid, perm_level, traverse_owned from materialized_permissions
[services/api: passenger] App 17550 output: order by user_uuid, target_uuid
[services/api: passenger] App 17550 output: 
[services/api: passenger] App 17550 output: check_permissions_against_full_refresh.full_recompute (3.3ms) 
[services/api: passenger] App 17550 output: select pq.origin_uuid as user_uuid, target_uuid, pq.val as perm_level, pq.traverse_owned from (
[services/api: passenger] App 17550 output:
[services/api: passenger] App 17550 output: WITH RECURSIVE
[services/api: passenger] App 17550 output: traverse_graph(origin_uuid, target_uuid, val, traverse_owned, starting_set) as (
[services/api: passenger] App 17550 output:
[services/api: passenger] App 17550 output: select uuid, uuid, 3, true, true from users
[services/api: passenger] App 17550 output:
[services/api: passenger] App 17550 output: union
[services/api: passenger] App 17550 output: (select traverse_graph.origin_uuid,
[services/api: passenger] App 17550 output: edges.head_uuid,
[services/api: passenger] App 17550 output: least(edges.val,
[services/api: passenger] App 17550 output: traverse_graph.val),
[services/api: passenger] App 17550 output: should_traverse_owned(edges.head_uuid, edges.val),
[services/api: passenger] App 17550 output: false
[services/api: passenger] App 17550 output: from permission_graph_edges as edges, traverse_graph
[services/api: passenger] App 17550 output: where traverse_graph.target_uuid = edges.tail_uuid
[services/api: passenger] App 17550 output: and (edges.tail_uuid like '_____-j7d0g-_______________' or
[services/api: passenger] App 17550 output: traverse_graph.starting_set)))
[services/api: passenger] App 17550 output: select traverse_graph.origin_uuid, target_uuid, max(val) as val, bool_or(traverse_owned) as traverse_owned from traverse_graph
[services/api: passenger] App 17550 output: group by (traverse_graph.origin_uuid, target_uuid)
[services/api: passenger] App 17550 output: ) as pq order by origin_uuid, target_uuid
[services/api: passenger] App 17550 output: 
[services/api: passenger] App 17550 output: AdminNotifier#new_user: processed outbound mail in 0.5ms
[services/api: passenger] App 17550 output:  (7.8ms) COMMIT
[services/api: passenger] App 17550 output:  (3.0ms) BEGIN
[services/api: passenger] App 17550 output: ApiClient Load (0.8ms) SELECT "api_clients".* FROM "api_clients" WHERE "api_clients"."is_trusted" = $1 AND "api_clients"."url_prefix" = $2 AND "api_clients"."name" = $3 LIMIT $4 [["is_trusted", true], ["url_prefix", ""], ["name", "SystemRootToken"], ["LIMIT", 1]]
[services/api: passenger] App 17571 output: [req-cyktna5qodmmc7fstzlu] "Path not found."
[services/api: passenger] App 17571 output: [req-cyktna5qodmmc7fstzlu] Error 1604608223+249df345: 404
[services/api: passenger] App 17550 output:  (0.9ms) SELECT clock_timestamp() AT TIME ZONE 'UTC'
[services/api: passenger] App 17571 output: {"method":"HEAD","path":"/","format":"html","controller":"StaticController","action":"home","status":404,"duration":19.41,"view":3.25,"request_id":"req-cyktna5qodmmc7fstzlu","client_ipaddr":"127.0.0.1","client_auth":null,"params":{},"@timestamp":"2020-11-05T20:30:23.809456340Z","@version":"1","message":"[404] HEAD / (StaticController#home)"}
[services/api: passenger] App 17550 output: ApiClient Create (1.2ms) INSERT INTO "api_clients" ("uuid", "owner_uuid", "modified_by_user_uuid", "modified_at", "name", "url_prefix", "created_at", "updated_at", "is_trusted") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING "id" [["uuid", "zzzzz-ozdt8-8ycdgf11jw76zou"], ["owner_uuid", "zzzzz-tpzed-000000000000000"], ["modified_by_user_uuid", "zzzzz-tpzed-000000000000000"], ["modified_at", "2020-11-05 20:30:23.804400"], ["name", "SystemRootToken"], ["url_prefix", ""], ["created_at", "2020-11-05 20:30:23.802991"], ["updated_at", "2020-11-05 20:30:23.804400"], ["is_trusted", true]]
[services/api: passenger] App 17550 output:  (0.5ms) SELECT clock_timestamp() AT TIME ZONE 'UTC'
[services/api: passenger] App 17550 output: Log Create (0.7ms) INSERT INTO "logs" ("uuid", "owner_uuid", "modified_by_user_uuid", "object_uuid", "event_at", "event_type", "summary", "properties", "created_at", "updated_at", "modified_at", "object_owner_uuid") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12) RETURNING "id" [["uuid", "zzzzz-57u5n-qr0dpntpjot5ei4"], ["owner_uuid", "zzzzz-tpzed-000000000000000"], ["modified_by_user_uuid", "zzzzz-tpzed-000000000000000"], ["object_uuid", "zzzzz-ozdt8-8ycdgf11jw76zou"], ["event_at", "2020-11-05 20:30:23.802991"], ["event_type", "create"], ["summary", "create of zzzzz-ozdt8-8ycdgf11jw76zou"], ["properties", "{\"old_etag\":null,\"old_attributes\":null,\"new_etag\":\"4gisp905j1jt0nd4c6gop6mfw\",\"new_attributes\":{\"id\":1,\"uuid\":\"zzzzz-ozdt8-8ycdgf11jw76zou\",\"owner_uuid\":\"zzzzz-tpzed-000000000000000\",\"modified_by_client_uuid\":null,\"modified_by_user_uuid\":\"zzzzz-tpzed-000000000000000\",\"modified_at\":\"2020-11-05T20:30:23.804400000Z\",\"name\":\"SystemRootToken\",\"url_prefix\":\"\",\"created_at\":\"2020-11-05T20:30:23.802991514Z\",\"updated_at\":\"2020-11-05T20:30:23.804400000Z\",\"is_trusted\":true}}"], ["created_at", "2020-11-05 20:30:23.814026"], ["updated_at", "2020-11-05 20:30:23.814466"], ["modified_at", "2020-11-05 20:30:23.814466"], ["object_owner_uuid", "zzzzz-tpzed-000000000000000"]]
[services/api: passenger] App 17550 output:  (0.3ms) NOTIFY logs, '2'
[services/api: passenger] App 17550 output:  (1.9ms) COMMIT
[-l] 2020-11-05 17:30:23.861 -03 [17542] ERROR: duplicate key value violates unique constraint "index_users_on_uuid"
[-l] 2020-11-05 17:30:23.861 -03 [17542] DETAIL: Key (uuid)=(zzzzz-tpzed-000000000000000) already exists.
[-l] 2020-11-05 17:30:23.861 -03 [17542] STATEMENT: INSERT INTO "users" ("uuid", "owner_uuid", "created_at", "modified_by_user_uuid", "modified_at", "email", "first_name", "last_name", "is_admin", "updated_at", "is_active") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) RETURNING "id"
[services/api: rake] rake aborted!
[services/api: rake] ActiveRecord::RecordNotUnique: PG::UniqueViolation: ERROR: duplicate key value violates unique constraint "index_users_on_uuid"
[services/api: rake] DETAIL: Key (uuid)=(zzzzz-tpzed-000000000000000) already exists.
[services/api: rake] : INSERT INTO "users" ("uuid", "owner_uuid", "created_at", "modified_by_user_uuid", "modified_at", "email", "first_name", "last_name", "is_admin", "updated_at", "is_active") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) RETURNING "id"
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `async_exec_params'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `block (2 levels) in exec_no_cache'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:610:in `block in exec_no_cache'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:581:in `block (2 levels) in log'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:580:in `block in log'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:571:in `log'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:609:in `exec_no_cache'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `execute_and_clear'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:130:in `exec_insert'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql/database_statements.rb:115:in `exec_insert'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:162:in `insert'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/query_cache.rb:21:in `insert'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:187:in `_insert_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:734:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/counter_cache.rb:184:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/locking/optimistic.rb:70:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/attribute_methods/dirty.rb:140:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:346:in `block in _create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:132:in `run_callbacks'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:816:in `_run_create_callbacks'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:346:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/timestamp.rb:102:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:705:in `create_or_update'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:342:in `block in create_or_update'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:132:in `run_callbacks'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:342:in `create_or_update'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:308:in `save!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/validations.rb:52:in `save!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:315:in `block in save!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `block in transaction'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `transaction'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:212:in `transaction'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:315:in `save!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/suppressor.rb:48:in `save!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:53:in `create!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:99:in `block in create!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:281:in `scoping'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:99:in `create!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:108:in `first_or_create!'
[services/api: rake] /media/psf/arvados/services/api/lib/current_api_client.rb:84:in `block in system_user'
[services/api: rake] /media/psf/arvados/services/api/lib/current_api_client.rb:287:in `check_cache'
[services/api: rake] /media/psf/arvados/services/api/lib/current_api_client.rb:77:in `system_user'
[services/api: rake] /media/psf/arvados/services/api/app/models/database_seeds.rb:11:in `block in install'
[services/api: rake] /media/psf/arvados/services/api/lib/update_permissions.rb:200:in `batch_update_permissions'
[services/api: rake] /media/psf/arvados/services/api/app/models/database_seeds.rb:10:in `install'
[services/api: rake] /media/psf/arvados/services/api/db/seeds.rb:9:in `<top (required)>'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bootsnap-1.4.7/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:55:in `load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bootsnap-1.4.7/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:55:in `load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies.rb:285:in `block in load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies.rb:257:in `load_dependency'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies.rb:285:in `load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/railties-5.2.4.3/lib/rails/engine.rb:554:in `block in load_seed'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/railties-5.2.4.3/lib/rails/engine.rb:672:in `with_inline_jobs'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/railties-5.2.4.3/lib/rails/engine.rb:554:in `load_seed'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/tasks/database_tasks.rb:281:in `load_seed'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/railties/databases.rake:194:in `block (2 levels) in <top (required)>'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/rake-13.0.1/exe/rake:27:in `<top (required)>'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli/exec.rb:74:in `load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli/exec.rb:74:in `kernel_load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli/exec.rb:28:in `run'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli.rb:463:in `exec'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli.rb:27:in `dispatch'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli.rb:18:in `start'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/exe/bundle:30:in `block in <top (required)>'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/friendly_errors.rb:124:in `with_friendly_errors'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/exe/bundle:22:in `<top (required)>'
[services/api: rake] /root/.gem/ruby/2.5.0/bin/bundle:23:in `load'
[services/api: rake] /root/.gem/ruby/2.5.0/bin/bundle:23:in `<main>'
[services/api: rake]
[services/api: rake] Caused by:
[services/api: rake] PG::UniqueViolation: ERROR: duplicate key value violates unique constraint "index_users_on_uuid"
[services/api: rake] DETAIL: Key (uuid)=(zzzzz-tpzed-000000000000000) already exists.
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `async_exec_params'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:611:in `block (2 levels) in exec_no_cache'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:610:in `block in exec_no_cache'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:581:in `block (2 levels) in log'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:580:in `block in log'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/notifications/instrumenter.rb:23:in `instrument'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract_adapter.rb:571:in `log'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:609:in `exec_no_cache'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql_adapter.rb:598:in `execute_and_clear'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_query'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:130:in `exec_insert'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/postgresql/database_statements.rb:115:in `exec_insert'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:162:in `insert'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/query_cache.rb:21:in `insert'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:187:in `_insert_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:734:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/counter_cache.rb:184:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/locking/optimistic.rb:70:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/attribute_methods/dirty.rb:140:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:346:in `block in _create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:132:in `run_callbacks'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:816:in `_run_create_callbacks'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:346:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/timestamp.rb:102:in `_create_record'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:705:in `create_or_update'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:342:in `block in create_or_update'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:132:in `run_callbacks'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/callbacks.rb:816:in `_run_save_callbacks'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/callbacks.rb:342:in `create_or_update'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:308:in `save!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/validations.rb:52:in `save!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:315:in `block in save!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:387:in `block in with_transaction_returning_status'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `block in transaction'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:239:in `block in within_new_transaction'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/transaction.rb:236:in `within_new_transaction'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/database_statements.rb:267:in `transaction'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:212:in `transaction'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:385:in `with_transaction_returning_status'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/transactions.rb:315:in `save!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/suppressor.rb:48:in `save!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/persistence.rb:53:in `create!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:99:in `block in create!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:281:in `scoping'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:99:in `create!'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/relation.rb:108:in `first_or_create!'
[services/api: rake] /media/psf/arvados/services/api/lib/current_api_client.rb:84:in `block in system_user'
[services/api: rake] /media/psf/arvados/services/api/lib/current_api_client.rb:287:in `check_cache'
[services/api: rake] /media/psf/arvados/services/api/lib/current_api_client.rb:77:in `system_user'
[services/api: rake] /media/psf/arvados/services/api/app/models/database_seeds.rb:11:in `block in install'
[services/api: rake] /media/psf/arvados/services/api/lib/update_permissions.rb:200:in `batch_update_permissions'
[services/api: rake] /media/psf/arvados/services/api/app/models/database_seeds.rb:10:in `install'
[services/api: rake] /media/psf/arvados/services/api/db/seeds.rb:9:in `<top (required)>'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bootsnap-1.4.7/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:55:in `load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bootsnap-1.4.7/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:55:in `load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies.rb:285:in `block in load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies.rb:257:in `load_dependency'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activesupport-5.2.4.3/lib/active_support/dependencies.rb:285:in `load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/railties-5.2.4.3/lib/rails/engine.rb:554:in `block in load_seed'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/railties-5.2.4.3/lib/rails/engine.rb:672:in `with_inline_jobs'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/railties-5.2.4.3/lib/rails/engine.rb:554:in `load_seed'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/tasks/database_tasks.rb:281:in `load_seed'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/activerecord-5.2.4.3/lib/active_record/railties/databases.rake:194:in `block (2 levels) in <top (required)>'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/rake-13.0.1/exe/rake:27:in `<top (required)>'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli/exec.rb:74:in `load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli/exec.rb:74:in `kernel_load'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli/exec.rb:28:in `run'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli.rb:463:in `exec'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor.rb:387:in `dispatch'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli.rb:27:in `dispatch'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/vendor/thor/lib/thor/base.rb:466:in `start'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/cli.rb:18:in `start'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/exe/bundle:30:in `block in <top (required)>'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/lib/bundler/friendly_errors.rb:124:in `with_friendly_errors'
[services/api: rake] /root/.gem/ruby/2.5.0/gems/bundler-1.17.3/exe/bundle:22:in `<top (required)>'
[services/api: rake] /root/.gem/ruby/2.5.0/bin/bundle:23:in `load'
[services/api: rake] /root/.gem/ruby/2.5.0/bin/bundle:23:in `<main>'
[services/api: rake] Tasks: TOP => db:setup => db:seed
[services/api: rake] (See full trace by running task with --trace)
[services/api: rake]  (0.1ms) SET TIME ZONE 'UTC'
[services/api: rake] ActiveRecord::InternalMetadata Load (0.5ms) SELECT "ar_internal_metadata".* FROM "ar_internal_metadata" WHERE "ar_internal_metadata"."key" = $1 LIMIT $2 [["key", "environment"], ["LIMIT", 1]]
[services/api: rake]  (0.3ms) BEGIN
[services/api: rake] ActiveRecord::InternalMetadata Create (1.2ms) INSERT INTO "ar_internal_metadata" ("key", "value", "created_at", "updated_at") VALUES ($1, $2, $3, $4) RETURNING "key" [["key", "environment"], ["value", "test"], ["created_at", "2020-11-05 20:30:22.840728"], ["updated_at", "2020-11-05 20:30:22.840728"]]
[services/api: rake]  (2.0ms) COMMIT
[services/api: rake]  (0.6ms) SET TIME ZONE 'UTC'
[services/api: rake]  (0.8ms) SELECT "schema_migrations"."version" FROM "schema_migrations" ORDER BY "schema_migrations"."version" ASC
[services/api: rake]  (0.5ms) SELECT clock_timestamp() AT TIME ZONE 'UTC'
[services/api: rake] User Load (1.0ms) SELECT "users".* FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."uuid" = $1 ORDER BY "users"."id" ASC LIMIT $2 [["uuid", "zzzzz-tpzed-000000000000000"], ["LIMIT", 1]]
[services/api: rake]  (0.2ms) BEGIN
[services/api: rake]  (0.6ms) SELECT clock_timestamp() AT TIME ZONE 'UTC'
[services/api: rake]  (0.7ms) SELECT COUNT(*) FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."uuid" = $1 AND (email = 'root') AND "users"."is_admin" = $2 [["uuid", "zzzzz-tpzed-000000000000000"], ["is_admin", true]]
[services/api: rake]  (0.7ms) SELECT COUNT(*) FROM "users" WHERE (redirect_to_user_uuid is null) AND "users"."uuid" = $1 AND (uuid not like '%-000000000000000') AND "users"."is_admin" = $2 [["uuid", "zzzzz-tpzed-000000000000000"], ["is_admin", true]]
[services/api: rake] User Create (1.2ms) INSERT INTO "users" ("uuid", "owner_uuid", "created_at", "modified_by_user_uuid", "modified_at", "email", "first_name", "last_name", "is_admin", "updated_at", "is_active") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11) RETURNING "id" [["uuid", "zzzzz-tpzed-000000000000000"], ["owner_uuid", "zzzzz-tpzed-000000000000000"], ["created_at", "2020-11-05 20:30:23.854378"], ["modified_by_user_uuid", "zzzzz-tpzed-000000000000000"], ["modified_at", "2020-11-05 20:30:23.854928"], ["email", "root"], ["first_name", "root"], ["last_name", ""], ["is_admin", true], ["updated_at", "2020-11-05 20:30:23.854928"], ["is_active", true]]
[services/api: rake]  (0.2ms) ROLLBACK
[services/api: rake]  (0.2ms) BEGIN
[services/api: rake]  (0.3ms) LOCK TABLE materialized_permissions
[services/api: rake]  (0.5ms) DELETE FROM materialized_permissions
[services/api: rake] refresh_permission_view.do (2.9ms) 
[services/api: rake] INSERT INTO materialized_permissions
[services/api: rake]
[services/api: rake] WITH RECURSIVE
[services/api: rake] traverse_graph(origin_uuid, target_uuid, val, traverse_owned, starting_set) as (
[services/api: rake]
[services/api: rake] select uuid, uuid, 3, true, true from users
[services/api: rake]
[services/api: rake] union
[services/api: rake] (select traverse_graph.origin_uuid,
[services/api: rake] edges.head_uuid,
[services/api: rake] least(edges.val,
[services/api: rake] traverse_graph.val),
[services/api: rake] should_traverse_owned(edges.head_uuid, edges.val),
[services/api: rake] false
[services/api: rake] from permission_graph_edges as edges, traverse_graph
[services/api: rake] where traverse_graph.target_uuid = edges.tail_uuid
[services/api: rake] and (edges.tail_uuid like '_____-j7d0g-_______________' or
[services/api: rake] traverse_graph.starting_set)))
[services/api: rake] select traverse_graph.origin_uuid, target_uuid, max(val) as val, bool_or(traverse_owned) as traverse_owned from traverse_graph
[services/api: rake] group by (traverse_graph.origin_uuid, target_uuid)
[services/api: rake]
[services/api: rake] 
[services/api: rake]  (1.1ms) COMMIT
{"PID":16970,"error":"[bundle exec rake db:setup]: error: exit status 1","level":"error","msg":"task failed","task":"seedDatabase","time":"2020-11-05T17:30:23.899735573-03:00"}
{"PID":16970,"level":"error","msg":"boot failed","time":"2020-11-05T17:30:23.899858023-03:00"}
{"PID":16970,"level":"info","msg":"task was never ready","task":"installPassenger:apps/workbench","time":"2020-11-05T17:30:23.899974718-03:00"}
{"PID":16970,"level":"info","msg":"task was never ready","task":"installPassenger:apps/workbench","time":"2020-11-05T17:30:23.899877148-03:00"}
[-l] 2020-11-05 17:30:23.900 -03 [17350] LOG: received smart shutdown request
[-l] 2020-11-05 17:30:23.901 -03 [17378] LOG: could not receive data from client: Connection reset by peer
[-l] 2020-11-05 17:30:23.906 -03 [17380] LOG: could not receive data from client: Connection reset by peer
[-l] 2020-11-05 17:30:23.908 -03 [17379] LOG: could not receive data from client: Connection reset by peer
[-l] 2020-11-05 17:30:23.913 -03 [17350] LOG: background worker "logical replication launcher" (PID 17362) exited with exit code 1
[services/api: passenger] Stopping web server...nginx: [alert] could not open error log file: open() "/tmp/arvados-server-boot-420120283/passenger-standalone.10ef56t/logs/error.log" failed (2: No such file or directory)
[services/api: passenger] 2020/11/05 17:30:23 [emerg] 17591#0: open() "/tmp/arvados-server-boot-420120283/passenger-standalone.10ef56t/nginx.conf" failed (2: No such file or directory)
[services/api: passenger] PhusionPassenger::DaemonController::StopError: Daemon 'Nginx' failed to start.
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:448:in `rescue in kill_daemon'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:445:in `kill_daemon'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:304:in `block (2 levels) in stop'
[services/api: passenger] /var/lib/arvados/lib/ruby/2.5.0/timeout.rb:93:in `block in timeout'
[services/api: passenger] /var/lib/arvados/lib/ruby/2.5.0/timeout.rb:103:in `timeout'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:303:in `block in stop'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:68:in `block in exclusive_lock'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:63:in `open'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller/lock_file.rb:63:in `exclusive_lock'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/vendor/daemon_controller.rb:301:in `stop'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:531:in `block in trapsafe_shutdown_and_cleanup'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:528:in `synchronize'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:528:in `trapsafe_shutdown_and_cleanup'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:76:in `rescue in run'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/start_command.rb:65:in `run'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/src/ruby_supportlib/phusion_passenger/standalone/main.rb:51:in `run!'
[services/api: passenger] /root/.gem/ruby/2.5.0/gems/passenger-6.0.2/bin/passenger:45:in `<top (required)>'
[services/api: passenger] /root/.gem/ruby/2.5.0/bin/passenger:23:in `load'
[services/api: passenger] /root/.gem/ruby/2.5.0/bin/passenger:23:in `<top (required)>'
[services/api: passenger] bundler: failed to load command: passenger (/root/.gem/ruby/2.5.0/bin/passenger)
{"PID":16970,"error":"context canceled","level":"warning","msg":"supervisor shut down","time":"2020-11-05T17:30:23.985653964-03:00"}
{"error":"context canceled","level":"info","msg":"exiting","time":"2020-11-05T17:30:23.985850750-03:00"}
    (1-1/1)