fm-orchestrator

#542 get_url_for() sometimes called without app_context causes SQL failures
Closed: Invalid Opened by sgallagh.

Closed: Invalid
Reopen Issue

I was attempting to run mbs-build local on a module with a lot of component packages running on a machine with a large number of CPUs. I set NUM_CONSECUTIVE_BUILDS = 24

When I attempt this, the mbs process hangs forever and the log file shows the following:

2017-05-08 20:02:39,375 - PoolThread-twisted.internet.reactor-0 - module_build_service - INFO - Connecting to koji 'https://koji.fedoraproject.org/kojihub'
2017-05-08 20:02:39,375 - PoolThread-twisted.internet.reactor-0 - koji - DEBUG - Opening new requests session
2017-05-08 20:02:39,376 - PoolThread-twisted.internet.reactor-0 - requests.packages.urllib3.connectionpool - DEBUG - Starting new HTTPS connection (1): koji.fedoraproject.org
2017-05-08 20:02:53,496 - PoolThread-twisted.internet.reactor-0 - requests.packages.urllib3.connectionpool - DEBUG - https://koji.fedoraproject.org:443 "POST /kojihub HTTP/1.1" 200 55512378
2017-05-08 20:03:14,618 - PoolThread-twisted.internet.reactor-0 - module_build_service - INFO - Downloading 14996 packages from Koji tag f26-modularity to /home/build/modulebuild/cache/koji_tags/f26-modularity
2017-05-08 20:33:23,462 - PoolThread-twisted.internet.reactor-0 - module_build_service - INFO - Creating local repository in /home/build/modulebuild/cache/koji_tags/f26-modularity
2017-05-08 20:33:23,463 - PoolThread-twisted.internet.reactor-0 - module_build_service - INFO - Executing command: ['/usr/bin/createrepo_c', u'/home/build/modulebuild/cache/koji_tags/f26-modularity']
2017-05-08 20:33:57,295 - PoolThread-twisted.internet.reactor-0 - module_build_service - DEBUG - Building module-build-macros.spec
2017-05-08 20:33:57,698 - PoolThread-twisted.internet.reactor-0 - module_build_service - DEBUG - Wrote srpm into /tmp/module_build_service-build-macrosGXuHGX/SRPMS/module-build-macros-0.1-1.test_7ad6eb4e.src.rpm
2017-05-08 20:33:57,699 - PoolThread-twisted.internet.reactor-0 - module_build_service - DEBUG - Starting build batch 1
2017-05-08 20:33:57,782 - PoolThread-twisted.internet.reactor-0 - module_build_service - INFO - Starting building artifact module-build-macros: /tmp/module_build_service-build-macrosGXuHGX/SRPMS/module-build-macros-0.1-1.test_7ad6eb4e.src.rpm
2017-05-08 20:33:57,783 - PoolThread-twisted.internet.reactor-0 - module_build_service - INFO - Executing command: ['mock', '-v', '-r', u'/home/build/results/module-bootstrap-master-20170508151121/config/mock-PoolThread-twisted.internet.reactor-0.cfg', '--init'], stdout log: /home/
build/results/module-bootstrap-master-20170508151121/results/module-build-macros-mock-stdout.log, stderr log: /home/build/results/module-bootstrap-master-20170508151121/results/module-build-macros-mock-stderr.log
2017-05-08 20:34:31,172 - PoolThread-twisted.internet.reactor-0 - module_build_service - INFO - Executing command: ['mock', '-v', '-r', u'/home/build/results/module-bootstrap-master-20170508151121/config/mock-PoolThread-twisted.internet.reactor-0.cfg', '--no-clean', '--rebuild', 
'/tmp/module_build_service-build-macrosGXuHGX/SRPMS/module-build-macros-0.1-1.test_7ad6eb4e.src.rpm', u'--resultdir=/home/build/results/module-bootstrap-master-20170508151121/results/PoolThread-twisted.internet.reactor-0'], stdout log: /home/build/results/module-bootstrap-master-20170508151121/results/module-build-macros-mock-stdout.log, stderr log: /home/build/results/module-bootstrap-master-20170508151121/results/module-build-macros-mock-stderr.log
2017-05-08 20:34:37,862 - PoolThread-twisted.internet.reactor-0 - module_build_service - INFO - <ModuleBuild bootstrap, id=1, stream=master, version=20170508151121, state 'build', batch 1, state_reason None>, state 1->2
2017-05-08 20:34:37,863 - PoolThread-twisted.internet.reactor-0 - module_build_service - DEBUG - WARNING: get_url_for() has been called without the Flask app_context. That can lead to SQLAlchemy errors caused by multiple session being used in the same time.
2017-05-08 20:34:42,875 - PoolThread-twisted.internet.reactor-0 - module_build_service - INFO - <ModuleBuild bootstrap, id=1, stream=master, version=20170508151121, state 'failed', batch 1, state_reason "(sqlite3.OperationalError) database is locked [SQL: u'SELECT component_builds.id AS component_builds_id, component_builds.package AS component_builds_package, component_builds.scmurl AS component_builds_scmurl, component_builds.format AS component_builds_format, component_builds.task_id AS component_builds_task_id, component_builds.ref AS component_builds_ref, component_builds.state AS component_builds_state, component_builds.state_reason AS component_builds_state_reason, component_builds.nvr AS component_builds_nvr, component_builds.tagged AS component_builds_tagged, component_builds.batch AS component_builds_batch, component_builds.module_id AS component_builds_module_id, component_builds.reused_component_id AS component_builds_reused_component_id \\nFROM component_builds \\nWHERE component_builds.module_id = ?'] [parameters: (1,)]">, state 2->4
2017-05-08 20:34:42,879 - PoolThread-twisted.internet.reactor-0 - module_build_service - DEBUG - WARNING: get_url_for() has been called without the Flask app_context. That can lead to SQLAlchemy errors caused by multiple session being used in the same time.
2017-05-08 20:34:47,891 - PoolThread-twisted.internet.reactor-0 - module_build_service - ERROR - Failed while handling MBSModule('local module build', 1, 1)
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/module_build_service/scheduler/consumer.py", line 136, in consume
    self.process_message(session, msg)
  File "/usr/lib/python2.7/site-packages/module_build_service/scheduler/consumer.py", line 217, in process_message
    state_reason=str(e))
  File "/usr/lib/python2.7/site-packages/module_build_service/models.py", line 231, in transition
    msg=self.json(),  # Note the state is "init" here...
  File "/usr/lib/python2.7/site-packages/module_build_service/models.py", line 288, in json
    "tasks": self.tasks(),
  File "/usr/lib/python2.7/site-packages/module_build_service/models.py", line 337, in tasks
    .options(lazyload('module_build'))\
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2703, in all
    return list(self)
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2855, in __iter__
    return self._execute_and_instances(context)
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2878, in _execute_and_instances
    result = conn.execute(querycontext.statement, self._params)
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 945, in execute
    return meth(self, multiparams, params)
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/sql/elements.py", line 263, in _execute_on_connection
    return connection._execute_clauseelement(self, multiparams, params)
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1053, in _execute_clauseelement
    compiled_sql, distilled_params
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1189, in _execute_context
    context)
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1402, in _handle_dbapi_exception
    exc_info
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/util/compat.py", line 203, in raise_from_cause
    reraise(type(exception), exception, tb=exc_tb, cause=cause)
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1182, in _execute_context
    context)
  File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/default.py", line 470, in do_execute
    cursor.execute(statement, parameters)
OperationalError: (sqlite3.OperationalError) database is locked [SQL: u'SELECT component_builds.id AS component_builds_id, component_builds.package AS component_builds_package, component_builds.scmurl AS component_builds_scmurl, component_builds.format AS component_builds_format, component_builds.task_id AS component_builds_task_id, component_builds.ref AS component_builds_ref, component_builds.state AS component_builds_state, component_builds.state_reason AS component_builds_state_reason, component_builds.nvr AS component_builds_nvr, component_builds.tagged AS component_builds_tagged, component_builds.batch AS component_builds_batch, component_builds.module_id AS component_builds_module_id, component_builds.reused_component_id AS component_builds_reused_component_id \nFROM component_builds \nWHERE component_builds.module_id = ?'] [parameters: (1,)]
2017-05-08 20:34:47,952 - PoolThread-twisted.internet.reactor-0 - module_build_service.scheduler - DEBUG - stop_condition checking <ModuleBuild bootstrap, id=1, stream=master, version=20170508151121, state 'wait', batch 1, state_reason None>, got False
2017-05-08 20:34:47,952 - PoolThread-twisted.internet.reactor-0 - moksha.hub - DEBUG - 'MBSConsumer' thread 139884106860288 | Going back to waiting on the incoming queue.
2017-05-08 20:34:47,952 - PoolThread-twisted.internet.reactor-0 - moksha.hub - DEBUG - 'MBSConsumer' thread 139884106860288 | Worker thread picking a message.
2017-05-08 20:34:47,953 - PoolThread-twisted.internet.reactor-0 - module_build_service - INFO - Skipping crypto validation for KojiBuildChange('a faked internal message', 2, 2, 1, 'module-build-macros', '0.1', '1.test_7ad6eb4e.src.rpm', module_build_id=None, state_reason=None)
2017-05-08 20:34:47,953 - PoolThread-twisted.internet.reactor-0 - module_build_service - DEBUG - Received KojiBuildChange('a faked internal message', 2, 2, 1, 'module-build-macros', '0.1', '1.test_7ad6eb4e.src.rpm', module_build_id=None, state_reason=None)
2017-05-08 20:34:47,955 - PoolThread-twisted.internet.reactor-0 - module_build_service - DEBUG - Received a message with an ID of "a faked internal message" and of type "KojiBuildChange"
2017-05-08 20:34:47,965 - PoolThread-twisted.internet.reactor-0 - module_build_service - DEBUG - No module associated with msg a faked internal message
2017-05-08 20:34:47,972 - PoolThread-twisted.internet.reactor-0 - module_build_service.scheduler - DEBUG - stop_condition checking <ModuleBuild bootstrap, id=1, stream=master, version=20170508151121, state 'wait', batch 1, state_reason None>, got False
2017-05-08 20:34:47,973 - PoolThread-twisted.internet.reactor-0 - moksha.hub - DEBUG - 'MBSConsumer' thread 139884106860288 | Going back to waiting on the incoming queue.

In particular, the line WARNING: get_url_for() has been called without the Flask app_context. That can lead to SQLAlchemy errors caused by multiple session being used in the same time. caught my attention. I looked at the code and the documentation for Flask and it seems like that context should be created the first time a flask transaction occurs and remain available, but it seems that there's an issue and each thread is getting its own app_context, which SQLAlchemy cannot handle.

CC @psabata @jkaluza

The system has python2-flask-0.11.1-5.fc26.noarch and module-build-service-1.3.21-1.fc27.noarch installed.

@sgallagh, do you see this issue frequently, or only once in a while?

Ping @sgallagh. Grooming the backlog here and trying to understand what kind of impact this has on you. Does it happen frequently, or only once in a while?

@ralph, I can't speak for Stephen or comment on this particular issue but I tried mbs-build local today and it just hanged right after building the macros package. I haven't investigated or reported the issue yet but if you can plan some time for a few MBS fixes this sprint, it'd be awesome.

We have an ancient checkout, 1df6f8e8ad47da85f7df446e227866bd0a83071a, which builds modules locally just fine, so it's not critical.

@ralph I haven't seen this lately. I suspect whatever was causing this was fixed incidentally elsewhere. I'll reopen it if I see it again.

Metadata Update from @sgallagh:
- Issue close_status updated to: Invalid
- Issue status updated to: Closed (was: Open)

Thanks!!

This issue has been migrated to Fedora Forge:
https://forge.fedoraproject.org/koji/mbs/issues/542

Please continue any further discussion there.
Metadata
None
None
None
None
None
Static archive. pagure.io was sunset in 2026; this is a read-only snapshot.
Red Hat Logo

Fedora is sponsored by Red Hat. Learn more about the relationship between Red Hat and Fedora »

© Red Hat, Inc. and others.