anchore-engine icon indicating copy to clipboard operation
anchore-engine copied to clipboard

Published 20 hours ago • verified publisher icon anchore

Response: {'httpcode': 500, 'anchore_error_raw': 'b\'"(psycopg2.errors.AdminShutdown) terminating connection due to administrator command\\\\nserver closed the connection unexpectedly

Open reddybhaskarvengala opened this issue 3 years ago • 1 comments

Hi Team,

We are using the docker based one (anchore-engine:v0.8.2) for scanning images. It was working fine but now we can see some error "Response: {'httpcode': 500, 'anchore_error_raw': 'b'"(psycopg2.errors.AdminShutdown) terminating connection due to administrator command". Could you please let us know what causes this error and fix for this issue.

Below are the logs.

Catalog-container: [service:catalog] 2021-03-20 05:32:54+0000 [-] [Thread-14] [anchore_engine.clients.services.internal/dispatch()] [ERROR] Failed client call to service simplequeue for url: http://queue:8228/v1/queues/watcher_tasks. Response: {'httpcode': 500, 'anchore_error_raw': 'b'"(psycopg2.errors.AdminShutdown) terminating connection due to administrator command\\nserver closed the connection unexpectedly\\n\\tThis probably means the server terminated abnormally\\n\\tbefore or while processing the request.\\n\\n[SQL: SELECT queuemeta.\\"queueName\\" AS \\"queuemeta_queueName\\", queuemeta.\\"userId\\" AS \\"queuemeta_userId\\", queuemeta.created_at AS queuemeta_created_at, queuemeta.last_updated AS queuemeta_last_updated, queuemeta.record_state_key AS queuemeta_record_state_key, queuemeta.record_state_val AS queuemeta_record_state_val, queuemeta.qlen AS queuemeta_qlen, queuemeta.max_outstanding_messages AS queuemeta_max_outstanding_messages, queuemeta.visibility_timeout AS queuemeta_visibility_timeout \\nFROM queuemeta \\nWHERE queuemeta.\\"queueName\\" = %(queueName_1)s AND queuemeta.\\"userId\\" = %(userId_1)s]\\n[parameters: {\'queueName_1\': \'watcher_tasks\', \'userId_1\': \'system\'}]\\n(Background on this error at: http://sqlalche.me/e/e3q8)"\n'', 'anchore_error_json': '(psycopg2.errors.AdminShutdown) terminating connection due to administrator command\nserver closed the connection unexpectedly\n\tThis probably means the server terminated abnormally\n\tbefore or while processing the request.\n\n[SQL: SELECT queuemeta."queueName" AS "queuemeta_queueName", queuemeta."userId" AS "queuemeta_userId", queuemeta.created_at AS queuemeta_created_at, queuemeta.last_updated AS queuemeta_last_updated, queuemeta.record_state_key AS queuemeta_record_state_key, queuemeta.record_state_val AS queuemeta_record_state_val, queuemeta.qlen AS queuemeta_qlen, queuemeta.max_outstanding_messages AS queuemeta_max_outstanding_messages, queuemeta.visibility_timeout AS queuemeta_visibility_timeout \nFROM queuemeta \nWHERE queuemeta."queueName" = %(queueName_1)s AND queuemeta."userId" = %(userId_1)s]\n[parameters: {'queueName_1': 'watcher_tasks', 'userId_1': 'system'}]\n(Background on this error at: http://sqlalche.me/e/e3q8)'} [service:catalog] 2021-03-20 05:32:54+0000 [-] [Thread-14] [anchore_engine.services.catalog/watcher_func()] [WARN] failed to process task this cycle: failed get url=http://queue:8228/v1/queues/watcher_tasks [service:catalog] 2021-03-20 05:32:54+0000 [-] [Thread-8392097] [anchore_engine.clients.services.internal/dispatch()] [ERROR] Failed client call to service simplequeue for url: http://queue:8228/v1/queues/watcher_tasks/is_inqueue. Response: {'httpcode': 500, 'anchore_error_raw': 'b'"(psycopg2.OperationalError) server closed the connection unexpectedly\\n\\tThis probably means the server terminated abnormally\\n\\tbefore or while processing the request.\\n\\n(Background on this error at: http://sqlalche.me/e/e3q8)"\n'', 'anchore_error_json': '(psycopg2.OperationalError) server closed the connection unexpectedly\n\tThis probably means the server terminated abnormally\n\tbefore or while processing the request.\n\n(Background on this error at: http://sqlalche.me/e/e3q8)'} [service:catalog] 2021-03-20 05:32:54+0000 [-] [Thread-8392097] [anchore_engine.services.catalog/schedule_watcher()] [WARN] failed to enqueue watcher task: failed post url=http://queue:8228/v1/queues/watcher_tasks/is_inqueue [service:catalog] 2021-03-20 05:32:54+0000 [-] [Thread-16] [anchore_engine.clients.services.internal/dispatch()] [ERROR] Failed client call to service simplequeue for url: http://queue:8228/v1/queues/watcher_tasks. Response: {'httpcode': 500, 'anchore_error_raw': 'b'"(psycopg2.OperationalError) could not connect to server: Connection refused\\n\\tIs the server running on host \\"db\\" (172.18.0.2) and accepting\\n\\tTCP/IP connections on port 5432?\\n\\n(Background on this error at: http://sqlalche.me/e/e3q8)"\n'', 'anchore_error_json': '(psycopg2.OperationalError) could not connect to server: Connection refused\n\tIs the server running on host "db" (172.18.0.2) and accepting\n\tTCP/IP connections on port 5432?\n\n(Background on this error at: http://sqlalche.me/e/e3q8)'} [service:catalog] 2021-03-20 05:32:54+0000 [-] [Thread-16] [anchore_engine.services.catalog/watcher_func()] [WARN] failed to process task this cycle: failed get url=http://queue:8228/v1/queues/watcher_tasks [service:catalog] 2021-03-20 05:32:54+0000 [-] [Thread-12] [anchore_engine.clients.services.internal/dispatch()] [ERROR] Failed client call to service simplequeue for url: http://queue:8228/v1/queues/watcher_tasks. Response: {'httpcode': 500, 'anchore_error_raw': 'b'"(psycopg2.OperationalError) could not connect to server: Connection refused\\n\\tIs the server running on host \\"db\\" (172.18.0.2) and accepting\\n\\tTCP/IP connections on port 5432?\\n\\n(Background on this error at: http://sqlalche.me/e/e3q8)"\n'', 'anchore_error_json': '(psycopg2.OperationalError) could not connect to server: Connection refused\n\tIs the server running on host "db" (172.18.0.2) and accepting\n\tTCP/IP connections on port 5432?\n\n(Background on this error at: http://sqlalche.me/e/e3q8)'} [service:catalog] 2021-03-20 05:32:54+0000 [-] [Thread-12] [anchore_engine.services.catalog/watcher_func()] [WARN] failed to process task this cycle: failed get url=http://queue:8228/v1/queues/watcher_tasks [service:catalog] 2021-03-20 05:33:01+0000 [-] Exception in thread Thread-20: [service:catalog] 2021-03-20 05:33:01+0000 [-] Traceback (most recent call last): [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1246, in _execute_context [service:catalog] 2021-03-20 05:33:01+0000 [-] cursor, statement, parameters, context [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 581, in do_execute [service:catalog] 2021-03-20 05:33:01+0000 [-] cursor.execute(statement, parameters) [service:catalog] 2021-03-20 05:33:01+0000 [-] psycopg2.errors.AdminShutdown: terminating connection due to administrator command [service:catalog] 2021-03-20 05:33:01+0000 [-] server closed the connection unexpectedly [service:catalog] 2021-03-20 05:33:01+0000 [-] This probably means the server terminated abnormally [service:catalog] 2021-03-20 05:33:01+0000 [-] before or while processing the request. [service:catalog] 2021-03-20 05:33:01+0000 [-] [service:catalog] 2021-03-20 05:33:01+0000 [-] [service:catalog] 2021-03-20 05:33:01+0000 [-] The above exception was the direct cause of the following exception: [service:catalog] 2021-03-20 05:33:01+0000 [-] [service:catalog] 2021-03-20 05:33:01+0000 [-] Traceback (most recent call last): [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/lib64/python3.6/threading.py", line 916, in _bootstrap_inner [service:catalog] 2021-03-20 05:33:01+0000 [-] self.run() [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/lib64/python3.6/threading.py", line 864, in run [service:catalog] 2021-03-20 05:33:01+0000 [-] self._target(*self._args, **self._kwargs) [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib/python3.6/site-packages/anchore_engine/services/catalog/init.py", line 251, in handle_service_watcher [service:catalog] 2021-03-20 05:33:01+0000 [-] anchore_services = db_services.get_all(session=dbsession) [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib/python3.6/site-packages/anchore_engine/db/db_services.py", line 57, in get_all [service:catalog] 2021-03-20 05:33:01+0000 [-] for result in our_results: [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/orm/query.py", line 3367, in iter [service:catalog] 2021-03-20 05:33:01+0000 [-] return self._execute_and_instances(context) [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/orm/query.py", line 3392, in _execute_and_instances [service:catalog] 2021-03-20 05:33:01+0000 [-] result = conn.execute(querycontext.statement, self._params) [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 982, in execute [service:catalog] 2021-03-20 05:33:01+0000 [-] return meth(self, multiparams, params) [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/sql/elements.py", line 287, in _execute_on_connection [service:catalog] 2021-03-20 05:33:01+0000 [-] return connection._execute_clauseelement(self, multiparams, params) [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1101, in _execute_clauseelement [service:catalog] 2021-03-20 05:33:01+0000 [-] distilled_params, [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1250, in _execute_context [service:catalog] 2021-03-20 05:33:01+0000 [-] e, statement, parameters, cursor, context [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1476, in _handle_dbapi_exception [service:catalog] 2021-03-20 05:33:01+0000 [-] util.raise_from_cause(sqlalchemy_exception, exc_info) [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 398, in raise_from_cause [service:catalog] 2021-03-20 05:33:01+0000 [-] reraise(type(exception), exception, tb=exc_tb, cause=cause) [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/util/compat.py", line 152, in reraise [service:catalog] 2021-03-20 05:33:01+0000 [-] raise value.with_traceback(tb) [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/engine/base.py", line 1246, in _execute_context [service:catalog] 2021-03-20 05:33:01+0000 [-] cursor, statement, parameters, context [service:catalog] 2021-03-20 05:33:01+0000 [-] File "/usr/local/lib64/python3.6/site-packages/sqlalchemy/engine/default.py", line 581, in do_execute [service:catalog] 2021-03-20 05:33:01+0000 [-] cursor.execute(statement, parameters) [service:catalog] 2021-03-20 05:33:01+0000 [-] sqlalchemy.exc.OperationalError: (psycopg2.errors.AdminShutdown) terminating connection due to administrator command [service:catalog] 2021-03-20 05:33:01+0000 [-] server closed the connection unexpectedly [service:catalog] 2021-03-20 05:33:01+0000 [-] This probably means the server terminated abnormally [service:catalog] 2021-03-20 05:33:01+0000 [-] before or while processing the request. [service:catalog] 2021-03-20 05:33:01+0000 [-] [service:catalog] 2021-03-20 05:33:01+0000 [-] [SQL: SELECT services.hostid AS services_hostid, services.servicename AS services_servicename, services.created_at AS services_created_at, services.last_updated AS services_last_updated, services.record_state_key AS services_record_state_key, services.record_state_val AS services_record_state_val, services.type AS services_type, services.version AS services_version, services.base_url AS services_base_url, services.short_description AS services_short_description, services.status AS services_status, services.status_message AS services_status_message, services.heartbeat AS services_heartbeat [service:catalog] 2021-03-20 05:33:01+0000 [-] FROM services] [service:catalog] 2021-03-20 05:33:01+0000 [-] (Background on this error at: http://sqlalche.me/e/e3q8) [service:catalog] 2021-03-20 05:33:01+0000 [-] [service:catalog] 2021-03-24 03:39:57+0000 [-] Unable to write to plugin cache /usr/local/lib64/python3.6/site-packages/twisted/plugins/dropin.cache: error number 13 [service:catalog] 2021-03-24 03:39:59+0000 [-] Unable to write to plugin cache /usr/local/lib/python3.6/site-packages/twisted/plugins/dropin.cache: error number 13 [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.twisted/makeService()] [INFO] Initializing configuration [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.twisted/makeService()] [INFO] Initializing logging [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.service/_register_instance_handlers()] [INFO] Registering api handlers [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.service/_process_stage_handlers()] [INFO] Processing init handlers for bootsrap stage: pre_config [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.service/_configure()] [INFO] Loading and initializing global configuration [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.service/_configure()] [INFO] Configuration complete [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.service/_process_stage_handlers()] [INFO] Processing init handlers for bootsrap stage: post_config [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.service/_process_stage_handlers()] [INFO] Processing init handlers for bootsrap stage: pre_db [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.service/_db_connect()] [INFO] Configuring db connection [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.service/_db_connect()] [INFO] Initializing database [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.service/_db_connect()] [INFO] DB connection initialization complete [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.service/_process_stage_handlers()] [INFO] Processing init handlers for bootsrap stage: post_db [service:catalog] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.subsys.object_store.manager/init()] [INFO] Object store clients: dict_keys(['db'])

[service:policy-engine] 2021-03-20 05:32:56+0000 [-] [Thread-8] [anchore_engine.services.policy_engine/handle_feed_sync_trigger()] [INFO] Feed Sync task creator activated [service:policy-engine] 2021-03-20 05:32:56+0000 [-] [Thread-8] [anchore_engine.clients.services.common/update_service_cache()] [WARN] cannot get service: (psycopg2.errors.AdminShutdown) terminating connection due to administrator command [service:policy-engine] server closed the connection unexpectedly [service:policy-engine] This probably means the server terminated abnormally [service:policy-engine] before or while processing the request. [service:policy-engine] [service:policy-engine] [SQL: SELECT services.hostid AS services_hostid, services.servicename AS services_servicename, services.created_at AS services_created_at, services.last_updated AS services_last_updated, services.record_state_key AS services_record_state_key, services.record_state_val AS services_record_state_val, services.type AS services_type, services.version AS services_version, services.base_url AS services_base_url, services.short_description AS services_short_description, services.status AS services_status, services.status_message AS services_status_message, services.heartbeat AS services_heartbeat [service:policy-engine] FROM services [service:policy-engine] WHERE services.servicename = %(servicename_1)s] [service:policy-engine] [parameters: {'servicename_1': 'simplequeue'}] [service:policy-engine] (Background on this error at: http://sqlalche.me/e/e3q8) [service:policy-engine] 2021-03-24 03:39:57+0000 [-] Unable to write to plugin cache /usr/local/lib64/python3.6/site-packages/twisted/plugins/dropin.cache: error number 13 [service:policy-engine] 2021-03-24 03:39:59+0000 [-] Unable to write to plugin cache /usr/local/lib/python3.6/site-packages/twisted/plugins/dropin.cache: error number 13 [service:policy-engine] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.twisted/makeService()] [INFO] Initializing configuration [service:policy-engine] 2021-03-24 03:40:00+0000 [-] [MainThread] [anchore_engine.twisted/makeService()] [INFO] Initializing logging

DB logs: ERROR: duplicate key value violates unique constraint "queue_pkey" DETAIL: Key ("queueId", "userId", "queueName")=(-1023999, system, images_to_analyze) already exists. STATEMENT: UPDATE queue SET "queueId"= -1023999, last_updated=1614334888 WHERE queue."queueId" = 5769619 AND queue."userId" = 'system' AND queue."queueName" = 'images_to_analyze' LOG: received fast shutdown request LOG: aborting any active transactions FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command FATAL: terminating connection due to administrator command LOG: autovacuum launcher shutting down LOG: shutting down LOG: database system is shut down

service-api logs [service:api] 2021-03-20 00:59:41+0000 [-] "127.0.0.1" - - [20/Mar/2021:00:59:41 +0000] "GET /health HTTP/1.1" 200 5 "-" "curl/7.61.1" [service:api] 2021-03-20 01:00:08+0000 [-] "100.108.143.56" - - [20/Mar/2021:01:00:08 +0000] "POST /v1/images HTTP/1.1" 200 3946 "-" "curl/7.29.0" [service:api] 2021-03-20 01:00:08+0000 [-] "100.108.143.56" - - [20/Mar/2021:01:00:08 +0000] "GET /v1/images/sha256:c61ffa3cf43ad02058feea2532c92fa069c91e5e424d3e5984475db2bb93138a/vuln/all HTTP/1.1" 200 34388 "-" "curl/7.29.0" [service:api] 2021-03-20 01:00:09+0000 [_GenericHTTPChannelProtocol,179518,100.108.143.56] [PoolThread-twisted.internet.reactor-1] [anchore_engine.clients.services.internal/dispatch()] [ERROR] Failed client call to service catalog for url: http://catalog:8228/v1/images. Response: {'httpcode': 404, 'anchore_error_raw': 'b'{\n "detail": {\n "error_codes": []\n },\n "httpcode": 404,\n "message": "image data not found in DB"\n}\n'', 'anchore_error_json': {'detail': {'error_codes': []}, 'httpcode': 404, 'message': 'image data not found in DB'}} [service:api] 2021-03-20 01:00:09+0000 [-] "100.108.143.56" - - [20/Mar/2021:01:00:08 +0000] "DELETE /v1/images/by_id/sha256:c61ffa3cf43ad02058feea2532c92fa069c91e5e424d3e5984475db2bb93138a?force=true HTTP/1.1" 200 132 "-" "curl/7.29.0" [service:api] 2021-03-20 01:00:11+0000 [-] "127.0.0.1" - - [20/Mar/2021:01:00:11 +0000] "GET /health HTTP/1.1" 200 5 "-" "curl/7.61.1" [service:api] 2021-03-20 01:00:14+0000 [-] [Thread-5329342] [anchore_engine.service/authz_heartbeat()] [INFO] Checking authz availability [service:api] 2021-03-20 01:00:42+0000 [-] "127.0.0.1" - - [20/Mar/2021:01:00:41 +0000] "GET /health HTTP/1.1" 200 5 "-" "curl/7.61.1" [service:api] 2021-03-20 01:01:12+0000 [-] "127.0.0.1" - - [20/Mar/2021:01:01:11 +0000] "GET /health HTTP/1.1" 200 5 "-" "curl/7.61.1" [service:api] 2021-03-20 01:01:15+0000 [-] [Thread-5329404] [anchore_engine.service/authz_heartbeat()] [INFO] Checking authz availabil

reddybhaskarvengala avatar Mar 24 '21 07:03 reddybhaskarvengala

Hi @BhaskiBuzz this usually indicates the PostgreSQL server was shut down, so you'll need to check the logs of the db itself to see what happened (or kubernetes pods if it was running in kubernetes). This can sometimes happen due to failure of liveness checks in k8s or other health check issues, or an admin restarting/terminating the db server itself.

zhill avatar Apr 17 '21 23:04 zhill