Can't complete query after 7.0 upgrade

C183653-china commented 1 year ago

Describe the bug After upgrade from 6.21 to 7.0, The SQL statement executed in the Query Tool stops automatically after 30 seconds. Rollback to 6.21, The results can be queried normally

Error message NA

Screenshots

Expected behavior Data should be output

Server (please complete the following information):

OS: [Windows 10]
Version: [7.0]
Mode: [Server]
Browser (if running in server mode): [chrome, Edge]
Package type: [Container]

Additional context ALLOW_SAVE_PASSWORD = True ALLOW_SAVE_TUNNEL_PASSWORD = False APP_COPYRIGHT = "Copyright (C) 2013 - 2023, The pgAdmin Development Team" APP_ICON = "pg-icon" APP_NAME = "pgAdmin 4" APP_RELEASE = 7 APP_REVISION = 0 APP_SUFFIX = "" APP_VERSION = "7.0" APP_VERSION_EXTN = ('.css', '.js', '.html', '.svg', '.png', '.gif', '.ico') APP_VERSION_INT = 70000 APP_VERSION_PARAM = "ver" AUTHENTICATION_SOURCES = ['internal'] AUTO_DISCOVER_SERVERS = True AZURE_CREDENTIAL_CACHE_DIR = "/var/lib/pgadmin/azurecredentialcache" CA_FILE = "/etc/ssl/certs/ca-certificates.crt" CHECK_EMAIL_DELIVERABILITY = False CHECK_SESSION_FILES_INTERVAL = 24 CHECK_SUPPORTED_BROWSER = True COMPRESS_LEVEL = 9 COMPRESS_MIMETYPES = ['text/html', 'text/css', 'text/xml', 'application/json', 'application/javascript'] COMPRESS_MIN_SIZE = 500 CONFIG_DATABASE_URI = "" CONSOLE_LOG_FORMAT = "%(asctime)s: %(levelname)s %(name)s: %(message)s" CONSOLE_LOG_LEVEL = 40 CONTENT_SECURITY_POLICY = "default-src ws: http: data: blob: 'unsafe-inline' 'unsafe-eval';" COOKIE_DEFAULT_DOMAIN = None COOKIE_DEFAULT_PATH = "/" DATA_DIR = "/var/lib/pgadmin" DEBUG = False DEFAULT_BINARY_PATHS = {'pg': '/usr/local/pgsql-15', 'pg-15': '/usr/local/pgsql-15', 'pg-14': '/usr/local/pgsql-14', 'pg-13': '/usr/local/pgsql-13', 'pg-12': '/usr/local/pgsql-12', 'pg-11': '/usr/local/pgsql-11', 'pg-10': '/usr/local/pgsql-10'} DEFAULT_SERVER = "127.0.0.1" DEFAULT_SERVER_PORT = 5050 DESKTOP_USER = "pgadmin4@pgadmin.org" EFFECTIVE_SERVER_PORT = 5050 ENABLE_BINARY_PATH_BROWSING = False ENABLE_PSQL = False ENHANCED_COOKIE_PROTECTION = False FILE_LOG_FORMAT = "%(asctime)s: %(levelname)s %(name)s: %(message)s" FILE_LOG_LEVEL = 30 HELP_PATH = "../../docs" IS_WIN = False KERBEROS_CCACHE_DIR = "/var/lib/pgadmin/krbccache" KRB_APP_HOST_NAME = "127.0.0.1" KRB_AUTO_CREATE_USER = True KRB_KTNAME = "" LANGUAGES = {'en': 'English', 'zh': 'Chinese (Simplified)', 'cs': 'Czech', 'fr': 'French', 'de': 'German', 'it': 'Italian', 'ja': 'Japanese', 'ko': 'Korean', 'pl': 'Polish', 'pt_BR': 'Portuguese (Brazilian)', 'ru': 'Russian', 'es': 'Spanish'} LDAP_ANONYMOUS_BIND = False LDAP_AUTO_CREATE_USER = True LDAP_BASE_DN = "" LDAP_BIND_FORMAT = "{LDAP_USERNAME_ATTRIBUTE}={LDAP_USERNAME},{LDAP_BASE_DN}" LDAP_BIND_USER = None LDAP_CA_CERT_FILE = "" LDAP_CERT_FILE = "" LDAP_CONNECTION_TIMEOUT = 10 LDAP_DN_CASE_SENSITIVE = False LDAP_KEY_FILE = "" LDAP_SEARCH_BASE_DN = "" LDAP_SEARCH_FILTER = "(objectclass=*)" LDAP_SEARCH_SCOPE = "SUBTREE" LDAP_SERVER_URI = "ldap://:" LDAP_USERNAME_ATTRIBUTE = "" LDAP_USE_STARTTLS = False LOGIN_ATTEMPT_FIELDS = ['password'] LOGIN_BANNER = "" LOG_FILE = "/dev/null" LOG_ROTATION_AGE = 1440 LOG_ROTATION_MAX_LOG_FILES = 90 LOG_ROTATION_SIZE = 10 MAIL_DEBUG = False MAIL_PORT = 25 MAIL_SERVER = "localhost" MAIL_USERNAME = "" MAIL_USE_SSL = False MAIL_USE_TLS = False MASTER_PASSWORD_REQUIRED = True MAX_LOGIN_ATTEMPTS = 3 MAX_QUERY_HIST_STORED = 20 MAX_SESSION_IDLE_TIME = 60 MFA_EMAIL_SUBJECT = None MFA_ENABLED = True MFA_FORCE_REGISTRATION = False MFA_SUPPORTED_METHODS = ['email', 'authenticator'] MODULE_BLACKLIST = ['test'] NODE_BLACKLIST = [] OAUTH2_AUTO_CREATE_USER = True OAUTH2_CONFIG = [{'OAUTH2_NAME': None, 'OAUTH2_DISPLAY_NAME': '', 'OAUTH2_CLIENT_ID': None, 'OAUTH2_CLIENT_SECRET': None, 'OAUTH2_TOKEN_URL': None, 'OAUTH2_AUTHORIZATION_URL': None, 'OAUTH2_SERVER_METADATA_URL': None, 'OAUTH2_API_BASE_URL': None, 'OAUTH2_USERINFO_ENDPOINT': None, 'OAUTH2_SCOPE': None, 'OAUTH2_USERNAME_CLAIM': None, 'OAUTH2_ICON': None, 'OAUTH2_BUTTON_COLOR': None}] ON_DEMAND_RECORD_COUNT = 1000 OVERRIDE_USER_INACTIVITY_TIMEOUT = True PASSWORD_LENGTH_MIN = 6 PG_DEFAULT_DRIVER = "psycopg3" PROXY_X_FOR_COUNT = 0 PROXY_X_HOST_COUNT = 1 PROXY_X_PORT_COUNT = 1 PROXY_X_PREFIX_COUNT = 1 PROXY_X_PROTO_COUNT = 1 SECURITY_CHANGEABLE = True SECURITY_EMAIL_SENDER = "no-reply@localhost" SECURITY_EMAIL_SUBJECT_PASSWORD_CHANGE_NOTICE = "Your password for pgAdmin 4 has been changed" SECURITY_EMAIL_SUBJECT_PASSWORD_NOTICE = "Your pgAdmin 4 password has been reset" SECURITY_EMAIL_SUBJECT_PASSWORD_RESET = "Password reset instructions for pgAdmin 4" SECURITY_EMAIL_VALIDATOR_ARGS = {'check_deliverability': False} SECURITY_POST_CHANGE_VIEW = "browser.change_password" SECURITY_RECOVERABLE = True SEND_FILE_MAX_AGE_DEFAULT = 31556952 SERVER_HEARTBEAT_TIMEOUT = 30 SERVER_MODE = True SESSION_COOKIE_DOMAIN = None SESSION_COOKIE_HTTPONLY = True SESSION_COOKIE_NAME = "pga4_session" SESSION_COOKIE_SAMESITE = "Lax" SESSION_COOKIE_SECURE = False SESSION_DB_PATH = "/var/lib/pgadmin/sessions" SESSION_EXPIRATION_TIME = 1 SESSION_SKIP_PATHS = ['/misc/ping'] SETTINGS_SCHEMA_VERSION = 35 SHARED_STORAGE = [] SHOW_GRAVATAR_IMAGE = True SQLALCHEMY_TRACK_MODIFICATIONS = False SQLITE_PATH = "/var/lib/pgadmin/pgadmin4.db" SQLITE_TIMEOUT = 500 STORAGE_DIR = "/var/lib/pgadmin/storage" STRICT_TRANSPORT_SECURITY = "max-age=31536000; includeSubDomains" STRICT_TRANSPORT_SECURITY_ENABLED = False SUPPORT_SSH_TUNNEL = True TEST_SQLITE_PATH = "/var/lib/pgadmin/test_pgadmin4.db" THREADED_MODE = True UPGRADE_CHECK_ENABLED = True UPGRADE_CHECK_KEY = "pgadmin4" UPGRADE_CHECK_URL = "https://www.pgadmin.org/versions.json" USER_INACTIVITY_TIMEOUT = 0 WEBSERVER_AUTO_CREATE_USER = True WEBSERVER_REMOTE_USER = "REMOTE_USER" WEB_SERVER = "Python" WTF_CSRF_HEADERS = ['X-pgA-CSRFToken'] X_CONTENT_TYPE_OPTIONS = "nosniff" X_FRAME_OPTIONS = "SAMEORIGIN" X_XSS_PROTECTION = "1; mode=block"

adityatoshniwal commented 1 year ago

@C183653-china Can you please share the pgAdmin logs? File->Runtime->View logs.

khushboovashi commented 1 year ago

Hi @C183653-china,

Do you face this in any specific scenario or are all the long-running queries getting stopped?

C183653-china commented 1 year ago

@khushboovashi Yes, Several users have given feedback on this issue after run long-running queries.

C183653-china commented 1 year ago

@adityatoshniwal only 3 Options in File, preferences, Reset Layout, Lock Layout.

and Docker image is from Repository: dockerhub/dpage/pgadmin4 Digest: sha256:8c3fd83a9856992e6d6b31662b613034e35b6dfae25e4b2b116b6c55de24a7e2

adityatoshniwal commented 1 year ago

@adityatoshniwal only 3 Options in File, preferences, Reset Layout, Lock Layout.

and Docker image is from Repository: dockerhub/dpage/pgadmin4 Digest: sha256:8c3fd83a9856992e6d6b31662b613034e35b6dfae25e4b2b116b6c55de24a7e2

@C183653-china then please share the docker logs for pgAdmin.

bart-jolink commented 1 year ago

I've got the same problem with version 7.0, but after 60 seconds instead. Screenshot from 2023-04-25 08-40-30 Running PgAdmin in kubernetes (docker image) with server mode The logs only show the following lines during this request: POST /misc/heartbeat/log GET /misc/ping

But retrying the request within the same query tool sometimes gives the following error:

2023-04-25 07:00:25,359: ERROR pgadmin: <asyncio.locks.Lock object at 0x7f67c96baaa0 [unlocked, waiters:1]> is bound to a different event loop Traceback (most recent call last): File "/pgadmin4/pgadmin/utils/driver/psycopg3/cursor.py", line 281, in execute return asyncio.run(self._execute(query, params)) File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run return loop.run_until_complete(main) File "/usr/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete return future.result() File "/pgadmin4/pgadmin/utils/driver/psycopg3/cursor.py", line 292, in _execute return await _async_cursor.execute(self, query, params) File "/venv/lib/python3.10/site-packages/psycopg/cursor_async.py", line 89, in execute async with self._conn.lock: File "/usr/lib/python3.10/asyncio/locks.py", line 14, in __aenter__ await self.acquire() File "/usr/lib/python3.10/asyncio/locks.py", line 106, in acquire fut = self._get_loop().create_future() File "/usr/lib/python3.10/asyncio/mixins.py", line 30, in _get_loop raise RuntimeError(f'{self!r} is bound to a different event loop') RuntimeError: <asyncio.locks.Lock object at 0x7f67c96baaa0 [unlocked, waiters:1]> is bound to a different event loop

with this output:

Screenshot from 2023-04-25 09-02-23

hussamhadi commented 1 year ago

Hi, I've run across this issue as well and I have some info to share about the exact way to reproduce it:

Run a long-duration query (preferably that takes longer than the SERVER_HEARTBEAT_TIMEOUT setting).
Observe the console log of the browser
the next time /misc/heartbeat/log is called, it will produce a 500 Server Error with the result of : {"success":0,"errormsg":"'AnonymousUser' object has no attribute 'id'","info":"","result":null,"data":null}
Other calls like /settings/store will give a 400 error with 'The CSRF session token is missing.'
The user will be logged out by then

Hope this helps!

fazzer14 commented 1 year ago

I'm getting the same issue and it makes v7 almost unusable. if you need someone to test anything or need more info from my machine or logs then just shout.

yogeshmahajan-1903 commented 1 year ago

@fazzer14 , @hussamhadi Could you please share pgadmin log file?

hussamhadi commented 1 year ago

@yogeshmahajan-1903 this is the log I get in the container (please be advised that IP addresses and domains have been redacted). I right-clicked one of the tables from my database -> View/Edit data -> All rows

xxx.xxx.xxx.xxx - - [09/May/2023:08:10:31 +0000] "POST /misc/cleanup HTTP/1.1" 200 0 "https://www.mydomain.com/browser/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:34 +0000] "POST /sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg HTTP/1.1" 200 1590 "https://www.mydomain.com/browser/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:34 +0000] "POST /settings/store HTTP/1.1" 200 77 "https://www.mydomain.com/browser/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:34 +0000] "GET /browser/browser.css?ver=70100 HTTP/1.1" 200 2787 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:35 +0000] "GET /browser/js/constants.js?ver=70100 HTTP/1.1" 200 455 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:35 +0000] "GET /user_management/current_user.js?ver=70100 HTTP/1.1" 200 288 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:35 +0000] "GET /browser/js/messages.js?ver=70100 HTTP/1.1" 200 757 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:35 +0000] "GET /browser/server/supported_servers.js?ver=70100 HTTP/1.1" 200 248 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:35 +0000] "GET /browser/js/endpoints.js?ver=70100 HTTP/1.1" 200 3025 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:35 +0000] "GET /tools/translations.js?ver=70100 HTTP/1.1" 200 321 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:35 +0000] "GET /browser/js/utils.js?ver=70100 HTTP/1.1" 200 2378 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:35 +0000] "POST /sqleditor/initialize/viewdata/6573302/3/table/2/3/22208522/22212656 HTTP/1.1" 200 80 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:35 +0000] "GET /sqleditor/status/6573302 HTTP/1.1" 200 156 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:37 +0000] "GET /sqleditor/status/6573302 HTTP/1.1" 200 135 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
[2023-05-09 08:10:40 +0000] [1] [WARNING] Worker with pid 1617 was terminated due to signal 9
[2023-05-09 08:10:40 +0000] [1633] [INFO] Booting worker with pid: 1633
2023-05-09 08:10:56,641: ERROR  pgadmin:    400 Bad Request: The CSRF session token is missing.
Traceback (most recent call last):
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 261, in protect
    validate_csrf(self._get_csrf_token())
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 103, in validate_csrf
    raise ValidationError("The CSRF session token is missing.")
wtforms.validators.ValidationError: The CSRF session token is missing.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/venv/lib/python3.10/site-packages/flask/app.py", line 1821, in full_dispatch_request
    rv = self.preprocess_request()
  File "/venv/lib/python3.10/site-packages/flask/app.py", line 2313, in preprocess_request
    rv = self.ensure_sync(before_func)()
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 229, in csrf_protect
    self.protect()
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 264, in protect
    self._error_response(e.args[0])
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 307, in _error_response
    raise CSRFError(reason)
flask_wtf.csrf.CSRFError: 400 Bad Request: The CSRF session token is missing.
2023-05-09 08:10:56,642: ERROR  pgadmin:    400 Bad Request: The CSRF session token is missing.
Traceback (most recent call last):
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 261, in protect
    validate_csrf(self._get_csrf_token())
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 103, in validate_csrf
    raise ValidationError("The CSRF session token is missing.")
wtforms.validators.ValidationError: The CSRF session token is missing.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/venv/lib/python3.10/site-packages/flask/app.py", line 1821, in full_dispatch_request
    rv = self.preprocess_request()
  File "/venv/lib/python3.10/site-packages/flask/app.py", line 2313, in preprocess_request
    rv = self.ensure_sync(before_func)()
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 229, in csrf_protect
    self.protect()
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 264, in protect
    self._error_response(e.args[0])
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 307, in _error_response
    raise CSRFError(reason)
flask_wtf.csrf.CSRFError: 400 Bad Request: The CSRF session token is missing.
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:56 +0000] "POST /settings/save_tree_state/ HTTP/1.1" 400 125 "https://www.mydomain.com/browser/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:56 +0000] "GET /sqleditor/view_data/start/6573302 HTTP/1.1" 400 125 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
2023-05-09 08:10:56,651: ERROR  pgadmin:    'AnonymousUser' object has no attribute 'id'
Traceback (most recent call last):
  File "/venv/lib/python3.10/site-packages/flask/app.py", line 1823, in full_dispatch_request
    rv = self.dispatch_request()
  File "/venv/lib/python3.10/site-packages/flask/app.py", line 1799, in dispatch_request
    return self.ensure_sync(self.view_functions[rule.endpoint])(**view_args)
  File "/pgadmin4/pgadmin/misc/__init__.py", line 172, in log_heartbeat
    status, msg = log_server_heartbeat(data)
  File "/pgadmin4/pgadmin/utils/heartbeat.py", line 24, in log_server_heartbeat
    manager = get_driver(PG_DEFAULT_DRIVER).connection_manager(int(data['sid'])
  File "/pgadmin4/pgadmin/utils/driver/psycopg3/__init__.py", line 111, in connection_manager
    managers = self._restore_connections_from_session()
  File "/pgadmin4/pgadmin/utils/driver/psycopg3/__init__.py", line 79, in _restore_connections_from_session
    user_id=current_user.id):
AttributeError: 'AnonymousUser' object has no attribute 'id'
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:56 +0000] "POST /misc/heartbeat/log HTTP/1.1" 500 107 "https://www.mydomain.com/browser/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
2023-05-09 08:10:56,714: ERROR  pgadmin:    400 Bad Request: The CSRF session token is missing.
Traceback (most recent call last):
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 261, in protect
    validate_csrf(self._get_csrf_token())
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 103, in validate_csrf
    raise ValidationError("The CSRF session token is missing.")
wtforms.validators.ValidationError: The CSRF session token is missing.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/venv/lib/python3.10/site-packages/flask/app.py", line 1821, in full_dispatch_request
    rv = self.preprocess_request()
  File "/venv/lib/python3.10/site-packages/flask/app.py", line 2313, in preprocess_request
    rv = self.ensure_sync(before_func)()
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 229, in csrf_protect
    self.protect()
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 264, in protect
    self._error_response(e.args[0])
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 307, in _error_response
    raise CSRFError(reason)
flask_wtf.csrf.CSRFError: 400 Bad Request: The CSRF session token is missing.
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:56 +0000] "GET /settings/get_tree_state/ HTTP/1.1" 400 125 "https://www.mydomain.com/browser/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
2023-05-09 08:10:56,787: ERROR  pgadmin:    400 Bad Request: The CSRF session token is missing.
Traceback (most recent call last):
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 261, in protect
    validate_csrf(self._get_csrf_token())
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 103, in validate_csrf
    raise ValidationError("The CSRF session token is missing.")
wtforms.validators.ValidationError: The CSRF session token is missing.

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/venv/lib/python3.10/site-packages/flask/app.py", line 1821, in full_dispatch_request
    rv = self.preprocess_request()
  File "/venv/lib/python3.10/site-packages/flask/app.py", line 2313, in preprocess_request
    rv = self.ensure_sync(before_func)()
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 229, in csrf_protect
    self.protect()
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 264, in protect
    self._error_response(e.args[0])
  File "/venv/lib/python3.10/site-packages/flask_wtf/csrf.py", line 307, in _error_response
    raise CSRFError(reason)
flask_wtf.csrf.CSRFError: 400 Bad Request: The CSRF session token is missing.
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:56 +0000] "POST /settings/store HTTP/1.1" 400 125 "https://www.mydomain.com/sqleditor/panel/6573302?is_query_tool=false&cmd_type=3&obj_type=table&obj_id=22212656&sgid=2&sid=3&did=22208522&server_type=pg" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"
xxx.xxx.xxx.xxx - - [09/May/2023:08:10:56 +0000] "POST /misc/heartbeat/stop HTTP/1.1" 200 87 "https://www.mydomain.com/browser/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/112.0.0.0 Safari/537.36"

yogeshmahajan-1903 commented 1 year ago

@hussamhadi

Could you please provide an example of long running query that reproduces this issue?(Is it DML/DDL type query)? Also when can you please check memory consumption while running above query ? - docker stats <contianer_id> 'Worker with pid 1617 was terminated due to signal 9' line in log indicates that python process restarted due to OOM error.

wwn0594 commented 1 year ago

This error seems can be 100% reproduced when I turn on Autocomplete on key press under version 7.1

Traceback (most recent call last):
  File "/pgadmin4/pgadmin/utils/driver/psycopg3/cursor.py", line 281, in execute
    return asyncio.run(self._execute(query, params))
  File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
    return future.result()
  File "/pgadmin4/pgadmin/utils/driver/psycopg3/cursor.py", line 292, in _execute
    return await _async_cursor.execute(self, query, params)
  File "/venv/lib/python3.10/site-packages/psycopg/cursor_async.py", line 89, in execute
    async with self._conn.lock:
  File "/usr/lib/python3.10/asyncio/locks.py", line 14, in __aenter__
    await self.acquire()
  File "/usr/lib/python3.10/asyncio/locks.py", line 106, in acquire
    fut = self._get_loop().create_future()
  File "/usr/lib/python3.10/asyncio/mixins.py", line 30, in _get_loop
    raise RuntimeError(f'{self!r} is bound to a different event loop')
RuntimeError: <asyncio.locks.Lock object at 0x7f5c2d9c7fd0 [unlocked, waiters:1]> is bound to a different event loop

fazzer14 commented 1 year ago

@hussamhadi

Could you please provide an example of long running query that reproduces this issue?(Is it DML/DDL type query)? Also when can you please check memory consumption while running above query ? - docker stats <contianer_id> 'Worker with pid 1617 was terminated due to signal 9' line in log indicates that python process restarted due to OOM error.

wwn0594 is correct. This is definitely to do with autocomplete being turned on. Switching it off stops the issue. You don't actually need a long running query just a select * from small_table will cause the bug if you leave it for a few minutes

hussamhadi commented 1 year ago

@hussamhadi

Could you please provide an example of long running query that reproduces this issue?(Is it DML/DDL type query)? Also when can you please check memory consumption while running above query ? - docker stats <contianer_id> 'Worker with pid 1617 was terminated due to signal 9' line in log indicates that python process restarted due to OOM error.

The query I'm running is SELECT * FROM public.MY_TABLE_NAME and due to the large number of records it indeed seems I'm running out of memory. Increasing the memory limit for the kubernetes pod gives the query more time to run indeed, so I guess the root cause for my issue is found. I'm not sure if @wwn0594 and @fazzer14 is the same.

adityatoshniwal commented 1 year ago

Thank you @wwn0594. That helped us reproduce the issue. We enabled autocomplete on key press and issue occurred.

Users who are facing this can Disable File->Preferences->Auto Completion->Autocomplete on key press please? for now meanwhile we're looking into it.

fire2 commented 1 year ago

We're also experiencing this issue since we upgraded to 7.0. We have "Autocomplete on key press" disabled, but all our longer-than-30s-queries timeout at exactly 30s.

stevecn commented 1 year ago

@hussamhadi Could you please provide an example of long running query that reproduces this issue?(Is it DML/DDL type query)? Also when can you please check memory consumption while running above query ? - docker stats <contianer_id> 'Worker with pid 1617 was terminated due to signal 9' line in log indicates that python process restarted due to OOM error.

The query I'm running is SELECT * FROM public.MY_TABLE_NAME and due to the large number of records it indeed seems I'm running out of memory. Increasing the memory limit for the kubernetes pod gives the query more time to run indeed, so I guess the root cause for my issue is found. I'm not sure if @wwn0594 and @fazzer14 is the same.

The reason for my issue was due to OOM (Out Of Memory). I increased the memory limit to 8G for the pod, which allowed me to run the query successfully. However, the memory did not free automatically after the query finished. This caused OOM to occur again when I attempted to run the same query a second time.

I suspect that the issue may be due to pgAdmin7 reading all data into memory and sending it to the client.

Memory usage after first query:

Memory usage after second query:

tchristie-meazure commented 1 year ago

We've also been experiencing issues with this, causing us not being able to upgrade from 6.21 (which we have a problem regarding https://github.com/pgadmin-org/pgadmin4/issues/5567).

UPDATE: After further debugging, it seems like our ingress controller in kubernetes was actually causing the gateway timeouts. After increasing our proxy-timeout values for nginx we were able to run long queries with no issues.

nginx.ingress.kubernetes.io/proxy-connect-timeout: "3600"
nginx.ingress.kubernetes.io/proxy-read-timeout: "3600"
nginx.ingress.kubernetes.io/proxy-send-timeout: "3600"

We are still seeing a ton of errors CSRF tokens do not match though.

BrandiATMuhkuh commented 1 year ago

I have the same issue. It works just fine of 6.x

ALLOW_SAVE_PASSWORD = True
ALLOW_SAVE_TUNNEL_PASSWORD = False
APP_COPYRIGHT = "Copyright (C) 2013 - 2023, The pgAdmin Development Team"
APP_ICON = "pg-icon"
APP_NAME = "pgAdmin 4"
APP_RELEASE = 7
APP_REVISION = 3
APP_SUFFIX = ""
APP_VERSION = "7.3"
APP_VERSION_EXTN = ('.css', '.js', '.html', '.svg', '.png', '.gif', '.ico')
APP_VERSION_INT = 70300
APP_VERSION_PARAM = "ver"
AUTHENTICATION_SOURCES = ['internal']
AUTO_DISCOVER_SERVERS = True
AZURE_CREDENTIAL_CACHE_DIR = "C:\Users\j\AppData\Roaming\pgAdmin\azurecredentialcache"
CA_FILE = "C:\Users\j\AppData\Local\Programs\pgAdmin 4\v7\web\cacert.pem"
CHECK_EMAIL_DELIVERABILITY = False
CHECK_SESSION_FILES_INTERVAL = 24
CHECK_SUPPORTED_BROWSER = True
COMPRESS_LEVEL = 9
COMPRESS_MIMETYPES = ['text/html', 'text/css', 'text/xml', 'application/json', 'application/javascript']
COMPRESS_MIN_SIZE = 500
CONFIG_DATABASE_URI = ""
CONSOLE_LOG_FORMAT = "%(asctime)s: %(levelname)s    %(name)s:   %(message)s"
CONSOLE_LOG_LEVEL = 30
CONTENT_SECURITY_POLICY = "default-src ws: http: data: blob: 'unsafe-inline' 'unsafe-eval';"
COOKIE_DEFAULT_DOMAIN = None
COOKIE_DEFAULT_PATH = "/"
DATA_DIR = "C:\Users\j\AppData\Roaming\pgAdmin"
DEBUG = False
DEFAULT_BINARY_PATHS = {'pg': '$DIR/../runtime', 'ppas': ''}
DEFAULT_SERVER = "127.0.0.1"
DEFAULT_SERVER_PORT = 5050
DESKTOP_USER = "pgadmin4@pgadmin.org"
DISABLED_LOCAL_PASSWORD_STORAGE = False
EFFECTIVE_SERVER_PORT = 62576
ENABLE_BINARY_PATH_BROWSING = False
ENABLE_PSQL = True
ENHANCED_COOKIE_PROTECTION = True
FILE_LOG_FORMAT = "%(asctime)s: %(levelname)s   %(name)s:   %(message)s"
FILE_LOG_LEVEL = 30
HELP_PATH = "../../../docs/en_US/html/"
IS_WIN = True
KERBEROS_CCACHE_DIR = "C:\Users\j\AppData\Roaming\pgAdmin\krbccache"
KEYRING_NAME = "Windows WinVaultKeyring"
KRB_APP_HOST_NAME = "127.0.0.1"
KRB_AUTO_CREATE_USER = True
KRB_KTNAME = "<KRB5_KEYTAB_FILE>"
LANGUAGES = {'en': 'English', 'zh': 'Chinese (Simplified)', 'cs': 'Czech', 'fr': 'French', 'de': 'German', 'id': 'Indonesian', 'it': 'Italian', 'ja': 'Japanese', 'ko': 'Korean', 'pl': 'Polish', 'pt_BR': 'Portuguese (Brazilian)', 'ru': 'Russian', 'es': 'Spanish'}
LDAP_ANONYMOUS_BIND = False
LDAP_AUTO_CREATE_USER = True
LDAP_BASE_DN = "<Base-DN>"
LDAP_BIND_FORMAT = "{LDAP_USERNAME_ATTRIBUTE}={LDAP_USERNAME},{LDAP_BASE_DN}"
LDAP_BIND_USER = None
LDAP_CA_CERT_FILE = ""
LDAP_CERT_FILE = ""
LDAP_CONNECTION_TIMEOUT = 10
LDAP_DN_CASE_SENSITIVE = False
LDAP_KEY_FILE = ""
LDAP_SEARCH_BASE_DN = "<Search-Base-DN>"
LDAP_SEARCH_FILTER = "(objectclass=*)"
LDAP_SEARCH_SCOPE = "SUBTREE"
LDAP_SERVER_URI = "ldap://<ip-address>:<port>"
LDAP_USERNAME_ATTRIBUTE = "<User-id>"
LDAP_USE_STARTTLS = False
LOGIN_ATTEMPT_FIELDS = ['password']
LOGIN_BANNER = ""
LOG_FILE = "C:\Users\j\AppData\Roaming\pgAdmin\pgadmin4.log"
LOG_ROTATION_AGE = 1440
LOG_ROTATION_MAX_LOG_FILES = 90
LOG_ROTATION_SIZE = 10
MAIL_DEBUG = False
MAIL_PORT = 25
MAIL_SERVER = "localhost"
MAIL_USERNAME = ""
MAIL_USE_SSL = False
MAIL_USE_TLS = False
MASTER_PASSWORD_HOOK = None
MASTER_PASSWORD_REQUIRED = True
MAX_LOGIN_ATTEMPTS = 3
MAX_QUERY_HIST_STORED = 20
MAX_SESSION_IDLE_TIME = 60
MFA_EMAIL_SUBJECT = None
MFA_ENABLED = False
MFA_FORCE_REGISTRATION = False
MFA_SUPPORTED_METHODS = ['email', 'authenticator']
MODULE_BLACKLIST = ['test']
NODE_BLACKLIST = []
OAUTH2_AUTO_CREATE_USER = True
OAUTH2_CONFIG = [{'OAUTH2_NAME': None, 'OAUTH2_DISPLAY_NAME': '<Oauth2 Display Name>', 'OAUTH2_CLIENT_ID': None, 'OAUTH2_CLIENT_SECRET': None, 'OAUTH2_TOKEN_URL': None, 'OAUTH2_AUTHORIZATION_URL': None, 'OAUTH2_SERVER_METADATA_URL': None, 'OAUTH2_API_BASE_URL': None, 'OAUTH2_USERINFO_ENDPOINT': None, 'OAUTH2_SCOPE': None, 'OAUTH2_USERNAME_CLAIM': None, 'OAUTH2_ICON': None, 'OAUTH2_BUTTON_COLOR': None}]
ON_DEMAND_RECORD_COUNT = 1000
OVERRIDE_USER_INACTIVITY_TIMEOUT = True
PASSWORD_LENGTH_MIN = 6
PG_DEFAULT_DRIVER = "psycopg3"
PROXY_X_FOR_COUNT = 1
PROXY_X_HOST_COUNT = 0
PROXY_X_PORT_COUNT = 1
PROXY_X_PREFIX_COUNT = 0
PROXY_X_PROTO_COUNT = 1
SECURITY_EMAIL_SENDER = "no-reply@localhost"
SECURITY_EMAIL_SUBJECT_PASSWORD_CHANGE_NOTICE = "Your password for pgAdmin 4 has been changed"
SECURITY_EMAIL_SUBJECT_PASSWORD_NOTICE = "Your pgAdmin 4 password has been reset"
SECURITY_EMAIL_SUBJECT_PASSWORD_RESET = "Password reset instructions for pgAdmin 4"
SECURITY_EMAIL_VALIDATOR_ARGS = {'check_deliverability': False}
SEND_FILE_MAX_AGE_DEFAULT = 31556952
SERVER_HEARTBEAT_TIMEOUT = 30
SERVER_MODE = False
SESSION_COOKIE_DOMAIN = None
SESSION_COOKIE_HTTPONLY = True
SESSION_COOKIE_NAME = "pga4_session"
SESSION_COOKIE_SAMESITE = "Lax"
SESSION_COOKIE_SECURE = False
SESSION_DB_PATH = "C:\Users\j\AppData\Roaming\pgAdmin\sessions"
SESSION_EXPIRATION_TIME = 7
SESSION_SKIP_PATHS = ['/misc/ping']
SETTINGS_SCHEMA_VERSION = 35
SHARED_STORAGE = []
SHOW_GRAVATAR_IMAGE = True
SQLALCHEMY_TRACK_MODIFICATIONS = False
SQLITE_PATH = "C:\Users\j\AppData\Roaming\pgAdmin\pgadmin4.db"
SQLITE_TIMEOUT = 500
STORAGE_DIR = "C:\Users\j\AppData\Roaming\pgAdmin\storage"
STRICT_TRANSPORT_SECURITY = "max-age=31536000; includeSubDomains"
STRICT_TRANSPORT_SECURITY_ENABLED = False
SUPPORT_SSH_TUNNEL = True
TEST_SQLITE_PATH = "C:\Users\j\AppData\Roaming\pgAdmin\test_pgadmin4.db"
THREADED_MODE = True
UPGRADE_CHECK_ENABLED = True
UPGRADE_CHECK_KEY = "pgadmin4"
UPGRADE_CHECK_URL = "https://www.pgadmin.org/versions.json"
USER_INACTIVITY_TIMEOUT = 0
WEBSERVER_AUTO_CREATE_USER = True
WEBSERVER_REMOTE_USER = "REMOTE_USER"
WEB_SERVER = "Python"
WTF_CSRF_HEADERS = ['X-pgA-CSRFToken']
X_CONTENT_TYPE_OPTIONS = "nosniff"
X_FRAME_OPTIONS = "SAMEORIGIN"
X_XSS_PROTECTION = "1; mode=block"

mad-it commented 1 year ago

I am facing the same issue running in Server mode. Since pgadmin 7.0.

What I noticed is since pgadmin 7.0 the sqleditor/query_tool/start/<id> waits for the result of the query, whereas < 6.21 the same POST returns quickly and then start calling sqleditor/poll/<id>.

The issue is indeed that 7.x waits and then you hit the Gateway Timeout limit, so the fix should be to revert the behavior and not wait until you get a result but in turn start the polling process.

PS: it seems that sqleditor/poll/<id> has been replaced with sqleditor/status/<id> in 7.x so maybe this behavioral change broke long queries altogether 🙈

In any case, reverting to 6.21 until this is resolved as we have some queries that take up to 5 minutes which makes 7.x unusable 😭

erichiller commented 1 year ago

Same issue here, the query window returns to the Messages tab.

The query ran doesn't seem to matter, it occurs even for queries that should have been near instant. The query from the attached image should have been instant, so the 20 sec 48 msec shown is not related to the query itself.

If you go to Data Output there are no results (and no columns).

The window acts as if it had completed successfully, only when looking at the logs does it become apparent that there has been an error. I'm using the stock dpage/pgadmin4 docker image.

Also, to your question @adityatoshniwal ,

Thank you @wwn0594. That helped us reproduce the issue. We enabled autocomplete on key press and issue occurred.

Users who are facing this can Disable File->Preferences->Auto Completion->Autocomplete on key press please? for now meanwhile we're looking into it.

I do not have, and have not had Autocomplete on key press enabled.

FaharAbbasRizvi commented 1 year ago

I have not seen any issue on Server mode as well as the Desktop of pgAdmin4 on the latest snapshot build:

https://www.postgresql.org/ftp/pgadmin/pgadmin4/snapshots/2023-07-18/

josephbedell commented 1 year ago

Was this ever fixed? I have version 7.3 and still have to disable Autocomplete in order to see Data results

mad-it commented 1 year ago

Its supposed to be fixed in 7.5 according to the changelog.

BrandiATMuhkuh commented 1 year ago

What fixed it for me was to select Reset Layout. Then it worked 🤷

pgadmin-org / pgadmin4

Can't complete query after 7.0 upgrade #6163