Message Collection Timeout: Large Repo/First Run

[sgoggins]

There is an issue with long running message collection first jobs, where they sometimes do not finish for large repos due to the following error:

Traceback (most recent call last):
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1969, in _exec_single_context
    self.dialect.do_execute(
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 922, in do_execute
    cursor.execute(statement, parameters)
psycopg2.OperationalError: SSL connection has been closed unexpectedly


The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/ubuntu/github/augur/augur/tasks/github/messages.py", line 43, in collect_github_messages
    process_large_issue_and_pr_message_collection(repo_id, repo_git, logger, manifest.key_auth, task_name, augur_db)
  File "/home/ubuntu/github/augur/augur/tasks/github/messages.py", line 109, in process_large_issue_and_pr_message_collection
    process_messages(all_data, task_name, repo_id, logger, augur_db)
  File "/home/ubuntu/github/augur/augur/tasks/github/messages.py", line 212, in process_messages
    augur_db.insert_data(contributors, Contributor, ["cntrb_id"])
  File "/home/ubuntu/github/augur/augur/application/db/session.py", line 188, in insert_data
    raise e
  File "/home/ubuntu/github/augur/augur/application/db/session.py", line 175, in insert_data
    connection.execute(stmnt)
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1416, in execute
    return meth(
           ^^^^^
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/sql/elements.py", line 516, in _execute_on_connection
    return connection._execute_clauseelement(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1639, in _execute_clauseelement
    ret = self._execute_context(
          ^^^^^^^^^^^^^^^^^^^^^^
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1848, in _execute_context
    return self._exec_single_context(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1988, in _exec_single_context
    self._handle_dbapi_exception(
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2343, in _handle_dbapi_exception
    raise sqlalchemy_exception.with_traceback(exc_info[2]) from e
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1969, in _exec_single_context
    self.dialect.do_execute(
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 922, in do_execute
    cursor.execute(statement, parameters)
sqlalchemy.exc.OperationalError: (psycopg2.OperationalError) SSL connection has been closed unexpectedly

[SQL: INSERT INTO augur_data.contributors (cntrb_id, cntrb_login, cntrb_email, cntrb_full_name, cntrb_company, cntrb_created_at, cntrb_location, cntrb_canonical, cntrb_last_used, gh_user_id, gh_login, gh_url, gh_html_url, gh_node_id, gh_avatar_url, gh_gravatar_id, gh_followers_url, gh_following_url, gh_gists_url, gh_starred_url, gh_subscriptions_url, gh_organizations_url, gh_repos_url, gh_events_url, gh_received_events_url, gh_type, gh_site_admin, tool_source, tool_version, data_source) VALUES (%(cntrb_id_m0)s::UUID, %(cntrb_login_m0)s, %(cntrb_email_m0)s, %(cntrb_full_name_m0)s, %(cntrb_company_m0)s, %(cntrb_created_at_m0)s, %(cntrb_location_m0)s, %(cntrb_canonical_m0)s, %(cntrb_last_used_m0)s, %(gh_user_id_m0)s, %(gh_login_m0)s, %(gh_url_m0)s, %(gh_html_url_m0)s, %(gh_node_id_m0)s, %(gh_avatar_url_m0)s, %(gh_gravatar_id_m0)s, %(gh_followers_url_m0)s, %(gh_following_url_m0)s, %(gh_gists_url_m0)s, %(gh_starred_url_m0)s, %(gh_subscriptions_url_m0)s, %(gh_organizations_url_m0)s, %(gh_repos_url_m0)s, %(gh_events_url_m0)s, %(gh_received_events_url_m0)s, %(gh_type_m0)s, %(gh_site_admin_m0)s, %(tool_source_m0)s, %(tool_version_m0)s, %(data_source_m0)s), (%(cntrb_id_m1)s::UUID, %(cntrb_login_m1)s, %(cntrb_email_m1)s, %(cntrb_full_name_m1)s, %(cntrb_company_m1)s, %(cntrb_created_at_m1)s, %(cntrb_location_m1)s, %(cntrb_canonical_m1)s, %(cntrb_last_used_m1)s, %(gh_user_id_m1)s, %(gh_login_m1)s, %(gh_url_m1)s, %(gh_html_url_m1)s, %(gh_node_id_m1)s, %(gh_avatar_url_m1)s, %(gh_gravatar_id_m1)s, %(gh_followers_url_m1)s, %(gh_following_url_m1)s, %(gh_gists_url_m1)s, %(gh_starred_url_m1)s, %(gh_subscriptions_url_m1)s, %(gh_organizations_url_m1)s, %(gh_repos_url_m1)s, %(gh_events_url_m1)s, %(gh_received_events_url_m1)s, %(gh_type_m1)s, %(gh_site_admin_m1)s, %(tool_source_m1)s, %(tool_version_m1)s, %(data_source_m1)s), (%(cntrb_id_m2)s::UUID, %(cntrb_login_m2)s, %(cntrb_email_m2)s, %(cntrb_full_name_m2)s, %(cntrb_company_m2)s, %(cntrb_created_at_m2)s, %(cntrb_location_m2)s, %(cntrb_canonical_m2)s, %(cntrb_last_used_m2)s, %(gh_user_id_m2)s, %(gh_login_m2)s, %(gh_url_m2)s, %(gh_html_url_m2)s, %(gh_node_id_m2)s, %(gh_avatar_url_m2)s, %(gh_gravatar_id_m2)s, %(gh_followers_url_m2)s, %(gh_following_url_m2)s, %(gh_gists_url_m2)s, %(gh_starred_url_m2)s, %(gh_subscriptions_url_m2)s, %(gh_organizations_url_m2)s, %(gh_repos_url_m2)s, %(gh_events_url_m2)s, %(gh_received_events_url_m2)s, %(gh_type_m2)s, %(gh_site_admin_m2)s, %(tool_source_m2)s, %(tool_version_m2)s, %(data_source_m2)s), (%(cntrb_id_m3)s::UUID, %(cntrb_login_m3)s, %(cntrb_email_m3)s, %(cntrb_full_name_m3)s, %(cntrb_company_m3)s, %(cntrb_created_at_m3)s, %(cntrb_location_m3)s, %(cntrb_canonical_m3)s, %(cntrb_last_used_m3)s, %(gh_user_id_m3)s, %(gh_login_m3)s, %(gh_url_m3)s, %(gh_html_url_m3)s, %(gh_node_id_m3)s, %(gh_avatar_url_m3)s, %(gh_gravatar_id_m3)s, %(gh_followers_url_m3)s, %(gh_following_url_m3)s, %(gh_gists_url_m3)s, %(gh_starred_url_m3)s, %(gh_subscriptions_url_m3)s, %(gh_organizations_url_m3)s, %(gh_repos_url_m3)s, %(gh_events_url_m3)s, %(gh_received_events_url_m3)s, %(gh_type_m3)s, %(gh_site_admin_m3)s, %(tool_source_m3)s, %(tool_version_m3)s, %(data_source_m3)s) ON CONFLICT (cntrb_id) DO UPDATE SET cntrb_id = excluded.cntrb_id, cntrb_login = excluded.cntrb_login, cntrb_email = excluded.cntrb_email, cntrb_full_name = excluded.cntrb_full_name, cntrb_company = excluded.cntrb_company, cntrb_created_at = excluded.cntrb_created_at, cntrb_location = excluded.cntrb_location, cntrb_canonical = excluded.cntrb_canonical, cntrb_last_used = excluded.cntrb_last_used, gh_user_id = excluded.gh_user_id, gh_login = excluded.gh_login, gh_url = excluded.gh_url, gh_html_url = excluded.gh_html_url, gh_node_id = excluded.gh_node_id, gh_avatar_url = excluded.gh_avatar_url, gh_gravatar_id = excluded.gh_gravatar_id, gh_followers_url = excluded.gh_followers_url, gh_following_url = excluded.gh_following_url, gh_gists_url = excluded.gh_gists_url, gh_starred_url = excluded.gh_starred_url, gh_subscriptions_url = excluded.gh_subscriptions_url, gh_organizations_url = excluded.gh_organizations_url, gh_repos_url = excluded.gh_repos_url, gh_events_url = excluded.gh_events_url, gh_received_events_url = excluded.gh_received_events_url, gh_type = excluded.gh_type, gh_site_admin = excluded.gh_site_admin, tool_source = excluded.tool_source, tool_version = excluded.tool_version, data_source = excluded.data_source]
[parameters: {'cntrb_id_m0': UUID('01000027-9900-0000-0000-000000000000'), 'cntrb_login_m0': 'ghost', 'cntrb_email_m0': None, 'cntrb_full_name_m0': None, 'cntrb_company_m0': None, 'cntrb_created_at_m0': None, 'cntrb_location_m0': None, 'cntrb_canonical_m0': None, 'cntrb_last_used_m0': None, 'gh_user_id_m0': 10137, 'gh_login_m0': 'ghost', 'gh_url_m0': 'https://api.github.com/users/ghost', 'gh_html_url_m0': 'https://github.com/ghost', 'gh_node_id_m0': 'MDQ6VXNlcjEwMTM3', 'gh_avatar_url_m0': 'https://avatars.githubusercontent.com/u/10137?v=4', 'gh_gravatar_id_m0': '', 'gh_followers_url_m0': 'https://api.github.com/users/ghost/followers', 'gh_following_url_m0': 'https://api.github.com/users/ghost/following{/other_user}', 'gh_gists_url_m0': 'https://api.github.com/users/ghost/gists{/gist_id}', 'gh_starred_url_m0': 'https://api.github.com/users/ghost/starred{/owner}{/repo}', 'gh_subscriptions_url_m0': 'https://api.github.com/users/ghost/subscriptions', 'gh_organizations_url_m0': 'https://api.github.com/users/ghost/orgs', 'gh_repos_url_m0': 'https://api.github.com/users/ghost/repos', 'gh_events_url_m0': 'https://api.github.com/users/ghost/events{/privacy}', 'gh_received_events_url_m0': 'https://api.github.com/users/ghost/received_events', 'gh_type_m0': 'User', 'gh_site_admin_m0': False, 'tool_source_m0': 'Pr comment task', 'tool_version_m0': '2.0', 'data_source_m0': 'Github API', 'cntrb_id_m1': UUID('0106da09-7500-0000-0000-000000000000'), 'cntrb_login_m1': 'stephengillie', 'cntrb_email_m1': None, 'cntrb_full_name_m1': None, 'cntrb_company_m1': None, 'cntrb_created_at_m1': None, 'cntrb_location_m1': None, 'cntrb_canonical_m1': None, 'cntrb_last_used_m1': None, 'gh_user_id_m1': 114952565, 'gh_login_m1': 'stephengillie', 'gh_url_m1': 'https://api.github.com/users/stephengillie', 'gh_html_url_m1': 'https://github.com/stephengillie', 'gh_node_id_m1': 'U_kgDOBtoJdQ', 'gh_avatar_url_m1': 'https://avatars.githubusercontent.com/u/114952565?v=4', 'gh_gravatar_id_m1': '', 'gh_followers_url_m1': 'https://api.github.com/users/stephengillie/followers', 'gh_following_url_m1': 'https://api.github.com/users/stephengillie/following{/other_user}', 'gh_gists_url_m1': 'https://api.github.com/users/stephengillie/gists{/gist_id}', 'gh_starred_url_m1': 'https://api.github.com/users/stephengillie/starred{/owner}{/repo}' ... 20 parameters truncated ... 'gh_login_m2': 'wingetbot', 'gh_url_m2': 'https://api.github.com/users/wingetbot', 'gh_html_url_m2': 'https://github.com/wingetbot', 'gh_node_id_m2': 'MDQ6VXNlcjYzODE2OTk5', 'gh_avatar_url_m2': 'https://avatars.githubusercontent.com/u/63816999?v=4', 'gh_gravatar_id_m2': '', 'gh_followers_url_m2': 'https://api.github.com/users/wingetbot/followers', 'gh_following_url_m2': 'https://api.github.com/users/wingetbot/following{/other_user}', 'gh_gists_url_m2': 'https://api.github.com/users/wingetbot/gists{/gist_id}', 'gh_starred_url_m2': 'https://api.github.com/users/wingetbot/starred{/owner}{/repo}', 'gh_subscriptions_url_m2': 'https://api.github.com/users/wingetbot/subscriptions', 'gh_organizations_url_m2': 'https://api.github.com/users/wingetbot/orgs', 'gh_repos_url_m2': 'https://api.github.com/users/wingetbot/repos', 'gh_events_url_m2': 'https://api.github.com/users/wingetbot/events{/privacy}', 'gh_received_events_url_m2': 'https://api.github.com/users/wingetbot/received_events', 'gh_type_m2': 'User', 'gh_site_admin_m2': False, 'tool_source_m2': 'Pr comment task', 'tool_version_m2': '2.0', 'data_source_m2': 'Github API', 'cntrb_id_m3': UUID('01023116-4900-0000-0000-000000000000'), 'cntrb_login_m3': 'azure-pipelines[bot]', 'cntrb_email_m3': None, 'cntrb_full_name_m3': None, 'cntrb_company_m3': None, 'cntrb_created_at_m3': None, 'cntrb_location_m3': None, 'cntrb_canonical_m3': None, 'cntrb_last_used_m3': None, 'gh_user_id_m3': 36771401, 'gh_login_m3': 'azure-pipelines[bot]', 'gh_url_m3': 'https://api.github.com/users/azure-pipelines%5Bbot%5D', 'gh_html_url_m3': 'https://github.com/apps/azure-pipelines', 'gh_node_id_m3': 'MDM6Qm90MzY3NzE0MDE=', 'gh_avatar_url_m3': 'https://avatars.githubusercontent.com/in/9426?v=4', 'gh_gravatar_id_m3': '', 'gh_followers_url_m3': 'https://api.github.com/users/azure-pipelines%5Bbot%5D/followers', 'gh_following_url_m3': 'https://api.github.com/users/azure-pipelines%5Bbot%5D/following{/other_user}', 'gh_gists_url_m3': 'https://api.github.com/users/azure-pipelines%5Bbot%5D/gists{/gist_id}', 'gh_starred_url_m3': 'https://api.github.com/users/azure-pipelines%5Bbot%5D/starred{/owner}{/repo}', 'gh_subscriptions_url_m3': 'https://api.github.com/users/azure-pipelines%5Bbot%5D/subscriptions', 'gh_organizations_url_m3': 'https://api.github.com/users/azure-pipelines%5Bbot%5D/orgs', 'gh_repos_url_m3': 'https://api.github.com/users/azure-pipelines%5Bbot%5D/repos', 'gh_events_url_m3': 'https://api.github.com/users/azure-pipelines%5Bbot%5D/events{/privacy}', 'gh_received_events_url_m3': 'https://api.github.com/users/azure-pipelines%5Bbot%5D/received_events', 'gh_type_m3': 'Bot', 'gh_site_admin_m3': False, 'tool_source_m3': 'Pr comment task', 'tool_version_m3': '2.0', 'data_source_m3': 'Github API'}]
(Background on this error at: https://sqlalche.me/e/20/e3q8)

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1119, in _rollback_impl
    self.engine.dialect.do_rollback(self.connection)
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 692, in do_rollback
    dbapi_connection.rollback()
psycopg2.InterfaceError: connection already closed

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/celery/app/trace.py", line 451, in trace_task
    R = retval = fun(*args, **kwargs)
                 ^^^^^^^^^^^^^^^^^^^^
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/celery/app/trace.py", line 734, in __protected_call__
    return self.run(*args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/ubuntu/github/augur/augur/tasks/github/messages.py", line 22, in collect_github_messages
    with GithubTaskManifest(logger) as manifest:
  File "/home/ubuntu/github/augur/augur/tasks/github/util/github_task_session.py", line 26, in __exit__
    self.augur_db.close()
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2466, in close
    self._close_impl(invalidate=False)
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 2535, in _close_impl
    transaction.close(invalidate)
  File "<string>", line 2, in close
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/orm/state_changes.py", line 139, in _go
    ret_value = fn(self, *arg, **kw)
                ^^^^^^^^^^^^^^^^^^^^
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/orm/session.py", line 1362, in close
    transaction.close()
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2576, in close
    self._do_close()
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2714, in _do_close
    self._close_impl()
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2700, in _close_impl
    self._connection_rollback_impl()
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2692, in _connection_rollback_impl
    self.connection._rollback_impl()
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1121, in _rollback_impl
    self._handle_dbapi_exception(e, None, None, None, None)
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 2343, in _handle_dbapi_exception
    raise sqlalchemy_exception.with_traceback(exc_info[2]) from e
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/base.py", line 1119, in _rollback_impl
    self.engine.dialect.do_rollback(self.connection)
  File "/home/ubuntu/github/virtualenvs/hosted/lib/python3.11/site-packages/sqlalchemy/engine/default.py", line 692, in do_rollback
    dbapi_connection.rollback()
sqlalchemy.exc.InterfaceError: (psycopg2.InterfaceError) connection already closed
(Background on this error at: https://sqlalche.me/e/20/rvf5)

Suggested Fix:

• Test for loss of connection
• If connection is lost, open a new one instead of losing all the data in a transaction and setting status to fail
• Big issue is that "core collection" includes a lot of jobs, and when this one fails, all of them get rerun on the same repository again and again.

Specifics:

• https://github.com/microsoft/winget-pkgs
• Received 2024-08-05 14:38:37.440960 UTC
• Started 2024-08-05 14:38:37.444868 UTC
• Failed 2024-08-09 06:51:56.523601 UTC

[sgoggins]

This query :

select msg_id, msg_timestamp, data_collection_date 
from message 
where repo_id=50183 order by msg_timestamp desc; 

shows that the message data is actually quite current:

msg_id	        msg_timestamp	        data_collection_date
1187399851	2024-08-07 23:24:23	2024-08-08 07:31:31
1187971112	2024-08-07 16:07:19	2024-08-08 16:24:42
1187971111	2024-08-07 15:50:44	2024-08-08 16:24:42

A reverse order of the same query show our earliest messages are from April, 2020:

msg_id	        msg_timestamp	        data_collection_date
32392606	2020-04-30 21:38:44	2023-05-11 06:24:54
32392607	2020-04-30 21:38:53	2023-05-11 06:24:54
32392608	2020-04-30 21:41:03	2023-05-11 06:24:54

So, our message collection seems "complete" as April 2020 is when this project started.

[ABrain7710]

Waiting to see if this occurs again