Docker build fails

[vidboda]

Hi,

was trying to update my VV docker - I deleted all the containers according to DOCKER.md to start from scratch.
I cloned the current vv repo, then added my NCBI key and then launched the build affter having pulled
docker-compose build --no-cache

and I got the following error:

root@restvv:~/rest_variantValidator# docker-compose pull
Pulling vdb     ... done
Pulling vvta    ... done
Pulling seqrepo ... done
Pulling restvv  ... done
root@restvv:~/rest_variantValidator# docker-compose build --no-cache
Building vdb
Sending build context to Docker daemon  2.815MB
Step 1/7 : FROM mysql:5.7
5.7: Pulling from library/mysql
e048d0a38742: Pull complete 
c7847c8a41cb: Pull complete 
351a550f260d: Pull complete 
8ce196d9d34f: Pull complete 
17febb6f2030: Pull complete 
d4e426841fb4: Pull complete 
fda41038b9f8: Pull complete 
f47aac56b41b: Pull complete 
a4a90c369737: Pull complete 
97091252395b: Pull complete 
84fac29d61e9: Pull complete 
Digest: sha256:8cf035b14977b26f4a47d98e85949a7dd35e641f88fc24aa4b466b36beecf9d6
Status: Downloaded newer image for mysql:5.7
 ---> be16cf2d832a
Step 2/7 : ENV MYSQL_RANDOM_ROOT_PASSWORD yes
 ---> Running in 3c1a4ec16089
Removing intermediate container 3c1a4ec16089
 ---> 144776638a76
Step 3/7 : ENV MYSQL_DATABASE validator
 ---> Running in 5a9c9ad716f3
Removing intermediate container 5a9c9ad716f3
 ---> 27cfe835cf01
Step 4/7 : ENV MYSQL_USER vvadmin
 ---> Running in 9641e3b4c58b
Removing intermediate container 9641e3b4c58b
 ---> 1d5458209762
Step 5/7 : ENV MYSQL_PASSWORD var1ant
 ---> Running in 171c9455c99c
Removing intermediate container 171c9455c99c
 ---> a73e612eb1d0
Step 6/7 : RUN apt-get update && apt-get install -y wget && rm -rf /var/lib/apt/lists/*
 ---> Running in 9a7cb1a7ddea
/bin/sh: apt-get: command not found
The command '/bin/sh -c apt-get update && apt-get install -y wget && rm -rf /var/lib/apt/lists/*' returned a non-zero code: 127
ERROR: Service 'vdb' failed to build : Build failed

Does that ring a bell to you?
thx

[vidboda]

it seems that you need to explicitely call for the mysql debian image, or change the package manager from apt-get to yum.

The simplest is likely to change in vdb_docker.df the line:

FROM mysql:5.7

to

FROM mysql:5.7-debian

[vidboda]

ok the build process seems to be ok, but launch fails.

I followed the following steps to recreate the containers and update the code:

# cd /root/rest_variantValidator
# docker-compose down
# docker-compose rm
# docker system prune -a --volumes
# mkdir ~/variantvalidator_data/share/logs
# git stash
# git pull

added email and NCBI API KEY in docker.ini, then I had to slightly modify vdb_docker.df

mysql:5.7

becomes

mysql:5.7-debian

and

apt-get update && apt-get install -y wget && rm -rf /var/lib/apt/lists/*

becomes

RUN apt-key adv --keyserver hkp://keyserver.ubuntu.com --recv-keys 467B942D3A79BD29 && apt-get update && apt-get install -y wget && rm -rf /var/lib/apt/lists/*

then:

# rm -r -f ~/variantvalidator_data/share/seqrepo/*
# docker-compose build --no-cache
# docker-compose up vvta
Ctrl-C when done
# docker-compose up vdb
Ctrl-C when done
# docker-compose up seqrepo
# docker-compose up -d                                                                       
Starting rest_variantvalidator_seqrepo_1 ... done                                                                               
Starting rest_variantvalidator_vvta_1    ... done                                                                                                                                                                                                                
Starting rest_variantvalidator_vdb_1     ... done                                                                               
Starting rest_variantvalidator_restvv_1  ... done 
# docker-compose up
Starting rest_variantvalidator_vvta_1    ... done
Starting rest_variantvalidator_seqrepo_1 ... done
Starting rest_variantvalidator_vdb_1     ... done
Starting rest_variantvalidator_restvv_1  ... done
Attaching to rest_variantvalidator_seqrepo_1, rest_variantvalidator_vdb_1, rest_variantvalidator_vvta_1, rest_variantvalidator_restvv_1
vdb_1      | 2023-03-08 11:09:51+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.41-1debian10 started.
vdb_1      | 2023-03-08 11:09:52+00:00 [Note] [Entrypoint]: Switching to dedicated user 'mysql'
vvta_1     | 
vvta_1     | PostgreSQL Database directory appears to contain a database; Skipping initialization
vvta_1     | 
vdb_1      | 2023-03-08 11:09:52+00:00 [Note] [Entrypoint]: Entrypoint script for MySQL Server 5.7.41-1debian10 started.
rest_variantvalidator_seqrepo_1 exited with code 0
vdb_1      | 2023-03-08T11:09:52.615513Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
vdb_1      | 2023-03-08T11:09:52.617419Z 0 [Note] mysqld (mysqld 5.7.41) starting as process 1 ...
vdb_1      | 2023-03-08T11:09:52.620318Z 0 [Note] InnoDB: PUNCH HOLE support available
vdb_1      | 2023-03-08T11:09:52.620345Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
vdb_1      | 2023-03-08T11:09:52.620349Z 0 [Note] InnoDB: Uses event mutexes
vdb_1      | 2023-03-08T11:09:52.620351Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
vdb_1      | 2023-03-08T11:09:52.620353Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.12
vdb_1      | 2023-03-08T11:09:52.620356Z 0 [Note] InnoDB: Using Linux native AIO
vdb_1      | 2023-03-08T11:09:52.620721Z 0 [Note] InnoDB: Number of pools: 1
vvta_1     | 2023-03-08 11:09:52.175 UTC [1] LOG:  starting PostgreSQL 12.6 (Debian 12.6-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
vvta_1     | 2023-03-08 11:09:52.175 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
vvta_1     | 2023-03-08 11:09:52.175 UTC [1] LOG:  listening on IPv6 address "::", port 5432
vvta_1     | 2023-03-08 11:09:53.072 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
vdb_1      | 2023-03-08T11:09:52.620857Z 0 [Note] InnoDB: Using CPU crc32 instructions
vvta_1     | 2023-03-08 11:09:53.451 UTC [26] LOG:  database system was shut down at 2023-03-08 11:09:42 UTC
vdb_1      | 2023-03-08T11:09:52.623424Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
vvta_1     | 2023-03-08 11:09:53.461 UTC [1] LOG:  database system is ready to accept connections
vdb_1      | 2023-03-08T11:09:52.631368Z 0 [Note] InnoDB: Completed initialization of buffer pool
vdb_1      | 2023-03-08T11:09:52.633988Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
vdb_1      | 2023-03-08T11:09:52.647019Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
vdb_1      | 2023-03-08T11:09:53.055476Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
vdb_1      | 2023-03-08T11:09:53.055605Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
vdb_1      | 2023-03-08T11:09:53.426302Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
vdb_1      | 2023-03-08T11:09:53.427350Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
vdb_1      | 2023-03-08T11:09:53.427377Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
vdb_1      | 2023-03-08T11:09:53.428404Z 0 [Note] InnoDB: Waiting for purge to start
vdb_1      | 2023-03-08T11:09:53.478778Z 0 [Note] InnoDB: 5.7.41 started; log sequence number 230398356
vdb_1      | 2023-03-08T11:09:53.479609Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
vdb_1      | 2023-03-08T11:09:53.479857Z 0 [Note] Plugin 'FEDERATED' is disabled.
vdb_1      | 2023-03-08T11:09:53.480899Z 0 [Note] InnoDB: Buffer pool(s) load completed at 230308 11:09:53
vdb_1      | 2023-03-08T11:09:53.486670Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
vdb_1      | 2023-03-08T11:09:53.486869Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
vdb_1      | 2023-03-08T11:09:53.486962Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. Please use TLSv1.2 or higher.
vdb_1      | 2023-03-08T11:09:53.486985Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. Please use TLSv1.2 or higher.
vdb_1      | 2023-03-08T11:09:53.487623Z 0 [Warning] CA certificate ca.pem is self signed.
vdb_1      | 2023-03-08T11:09:53.487778Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
vdb_1      | 2023-03-08T11:09:53.488444Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
vdb_1      | 2023-03-08T11:09:53.488606Z 0 [Note] IPv6 is available.
vdb_1      | 2023-03-08T11:09:53.488696Z 0 [Note]   - '::' resolves to '::';
vdb_1      | 2023-03-08T11:09:53.488796Z 0 [Note] Server socket created on IP: '::'.
vdb_1      | 2023-03-08T11:09:53.494529Z 0 [Warning] Insecure configuration for --pid-file: Location '/var/run/mysqld' in the path is accessible to all OS users. Consider choosing a different directory.
vdb_1      | 2023-03-08T11:09:53.504179Z 0 [Note] Event Scheduler: Loaded 0 events
vdb_1      | 2023-03-08T11:09:53.504489Z 0 [Note] mysqld: ready for connections.
vdb_1      | Version: '5.7.41'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  MySQL Community Server (GPL)
restvv_1   | [2023-03-08 11:09:54 +0000] [7] [INFO] Starting gunicorn 20.1.0
restvv_1   | [2023-03-08 11:09:54 +0000] [7] [INFO] Listening at: http://0.0.0.0:8000 (7)
restvv_1   | [2023-03-08 11:09:54 +0000] [7] [INFO] Using worker: gthread
restvv_1   | [2023-03-08 11:09:54 +0000] [8] [INFO] Booting worker with pid: 8
restvv_1   | Exception ignored in: <function UTA_postgresql.__del__ at 0x7f3c19daf6d0>
restvv_1   | Traceback (most recent call last):
restvv_1   |   File "/usr/local/lib/python3.10/site-packages/vvhgvs/dataproviders/uta.py", line 515, in __del__
restvv_1   |     self.close()
restvv_1   |   File "/usr/local/lib/python3.10/site-packages/vvhgvs/dataproviders/uta.py", line 519, in close
restvv_1   |     self._pool.closeall()
restvv_1   | AttributeError: 'UTA_postgresql' object has no attribute '_pool'
restvv_1   | [2023-03-08 11:09:54 +0000] [7] [INFO] Shutting down: Master
restvv_1   | [2023-03-08 11:09:54 +0000] [7] [INFO] Reason: Worker failed to boot.
rest_variantvalidator_restvv_1 exited with code 3

Then rest_variantvalidator_restvv_1 fails to launch.

I retried with the following end sequence and code from rest_variantValidator release 2.2.0 instead of just cloning the repo or pulling new code, but same error at startup:

# docker-compose up vvta
Ctrl-C when done
# docker-compose up vdb
Ctrl-C when done
# docker-compose up

Any help would be highly appreciated.

[ifokkema]

I'm no expert on Docker (actually, I rarely use it), but I remember changes have been made recently about whether or not VV had to use pooling of database connections. Remember those race conditions that we saw? The error is about this file. It seems that perhaps UTA is confused about whether to use pooling or not. Do you think you have write access to /usr/local/lib/python3.10/site-packages/vvhgvs/dataproviders/uta.py? If so, you could edit the code to fix that bug.

[vidboda]

Thx @ifokkema,

however, the code on this file looks good to me, as far as I can tell.

In def connect(), if pooling is enabled, the object is correctly instanciated:

if self.pooling:
    _logger.info("Using UTA ThreadedConnectionPool")
    self._pool = psycopg2.pool.ThreadedConnectionPool(vvhgvs.global_config.uta.pool_min,
                                                              vvhgvs.global_config.uta.pool_max, **conn_args)

then self._pool should be accessible when closing:

def close(self):
        if self.pooling:
            self._pool.closeall() 

Then I'm not sure of what is wrong here. Or maybe the pooling attribute has changed after the first connection, from False to True? That would be weird. And the code is 2 yaers old. Well...

[ifokkema]

I didn't mean that the bug is necessarily in this file; it might as well be in its usage outside of this file. I don't see self.pooling set other than at the time the class is created, so it's possible that external code modifies the variable. Also, external code could have resulted in the loss of the self._pool variable. Either way, the error indicates pooling is true while self._pool isn't set. Checking for self._pool as well as self.pooling will likely remove the error, although indeed, it may not actually fix the origin of the bug. So while in the long run, the bug should properly be fixed, right now, you could perhaps modify the code such that the error is avoided.

[vidboda]

well, you're probably right, as usual, but in my opinion just checking could lead to improper closing of the connection, or worse, to leave it open which would quickly result in a freeze of the whole system due to a lack of available connections. I'll maybe make some tests tomorrow. thanks anyway.

[ifokkema]

Well, the connection, if it exists, will still be closed, of course. The else will simply take care of it.

Anyway, in the worst-case scenario, the connection should close when the Python program ends.

[vidboda]

ok I'll give it a try asap with a try/except block

Well, the connection, if it exists, will still be closed, of course. The else will simply take care of it.

But I wouldn't bet on it. From my experience, depending on the way you handle psycopg2 connections, the syntax differs then if a connection is opened with a connexion pool you must release it the same way - then the else may fail as well. But it may work if the self.pooling boolean has been modify in the meantime, right.

Anyway, in the worst-case scenario, the connection should close when the Python program ends.

again, not sure about that, even if it seems good sense. I've had the case in a flask app where connections were not correctly closed, and when ran as a wsgi app, connections remained opened, and eventually led to the system freeze. Apache kind of keeps the scripts in memory, to be able to execute them quicker (such as in mod_perl, for example). You probably know better on this.

[ifokkema]

ok I'll give it a try asap with a try/except block

That may actually lead to the connection not being closed, as the else will never get executed. If you just adapt the if, the else will be run if there's no pool to close.

Well, the connection, if it exists, will still be closed, of course. The else will simply take care of it.

But I wouldn't bet on it. From my experience, depending on the way you handle psycopg2 connections, the syntax differs then if a connection is opened with a connexion pool you must release it the same way - then the else may fail as well.

Sure, but there's nothing to release as there is no self._pool. So, unless self._pool has been removed, the connection was never pooled. And the else is sufficiently protected against failure as it checks if there is a connection at all.

But it may work if the self.pooling boolean has been modify in the meantime, right.

That's my guess, indeed, but only a guess. It may also be that the connection has already closed and self._pool got removed.

Anyway, in the worst-case scenario, the connection should close when the Python program ends.

again, not sure about that, even if it seems good sense. I've had the case in a flask app where connections were not correctly closed, and when ran as a wsgi app, connections remained opened, and eventually led to the system freeze. Apache kind of keeps the scripts in memory, to be able to execute them quicker (such as in mod_perl, for example). You probably know better on this.

Well, I hardly use WSGI, so I wouldn't know better, actually... I just quickly googled my assumption that the connections would be closed, the first link mentioned that indeed this would happen, and I didn't look further. So you might be right there! Either way, it's worth a shot, as now, nothing is working.

[Peter-J-Freeman]

@beboche @ifokkema

I have updated the docker with mysql:5.7-debian

AttributeError: 'UTA_postgresql' object has no attribute '_pool'
Have seen this before. Think it is when VVTA fails to connect.

I'll see if I can build the container at my end

[vidboda]

Nice I'll give it a try asap

[Peter-J-Freeman]

One sec. forgot to add it to the API. Doing now

[vidboda]

Ok I have a bunch of meetings today, anyway Le 19 avr. 2023 à 10:06, Peter J. Freeman ***@***.***> a écrit : One sec. forgot to add it to the API. Doing now — Reply to this email directly, view it on GitHub<#91 (comment)>, or unsubscribe<https://github.com/notifications/unsubscribe-auth/AG6LYSKHUB6D2X5DT43DUC3XB6MJHANCNFSM6AAAAAAVSLN2H4>. You are receiving this because you were mentioned.Message ID: ***@***.***>

[vidboda]

@Peter-J-Freeman is it ok from your side?

[Peter-J-Freeman]

I ran it this afternoon and everything installed.