Bad Gateway Error when commiting with outputs

[svdaddio]

When I attemt to commit changes to Minemeld that include outputs using data from a local DB. Does anyone have any insight into what the Bad Gateway error signifies? I have attached a screenshot of the error message I am receiving.

[svdaddio]

Is anyone else experiencing anything like this? I'm considering tearing the whole server down and building a new one from scratch.

[lmori]

Does it happen on every commit or only for specific config changes?

[svdaddio]

It happens on almost every commit. Every once in a while, it will allow a commit through.

[xhoms]

Hi @svdaddio,

could you take a look at the minemeld-web log file to see is there is any significative error message?

(/opt/minemeld/log/minemeld-web.log)

[svdaddio]

@xhoms

It looks like there is a common error in the web log when I get the gateway error.

[2018-12-27 17:05:25 EST] [113763] [INFO] AUDIT - {"msg": null, "action": "POST /config/commit", "params": [["jsonbody", "{\"version\": \"420c0a16-cdd8-45a6-a1a5-c1d30be2a537\"}"]], "user": "admin/admin"}
[2018-12-27 17:05:55 +0000] [55777] [CRITICAL] WORKER TIMEOUT (pid:113763)
[2018-12-27 17:05:55 EST] [113763] [DEBUG] redis connection pool: in use: 1 available: 1
[2018-12-27 17:06:25 +0000] [113763] [WARNING] Worker graceful timeout (pid:113763)
[2018-12-27 17:06:26 EST] [113763] [DEBUG] redis connection pool: in use: 0 available: 2
[2018-12-27 17:06:27 +0000] [113763] [INFO] Worker exiting (pid: 113763)
class Subsystem(tuple):
    'Subsystem(authdb, attrs, enabled, enabled_default)'

    __slots__ = ()

    _fields = ('authdb', 'attrs', 'enabled', 'enabled_default')

    def __new__(_cls, authdb, attrs, enabled, enabled_default):
        'Create new instance of Subsystem(authdb, attrs, enabled, enabled_default)'
        return _tuple.__new__(_cls, (authdb, attrs, enabled, enabled_default))

    @classmethod
    def _make(cls, iterable, new=tuple.__new__, len=len):
        'Make a new Subsystem object from a sequence or iterable'
        result = new(cls, iterable)
        if len(result) != 4:
            raise TypeError('Expected 4 arguments, got %d' % len(result))
        return result

    def __repr__(self):
        'Return a nicely formatted representation string'
        return 'Subsystem(authdb=%r, attrs=%r, enabled=%r, enabled_default=%r)' % self

    def _asdict(self):
        'Return a new OrderedDict which maps field names to their values'
        return OrderedDict(zip(self._fields, self))

    def _replace(_self, **kwds):
        'Return a new Subsystem object replacing specified fields with new values'
        result = _self._make(map(kwds.pop, ('authdb', 'attrs', 'enabled', 'enabled_default'), _self))
        if kwds:
            raise ValueError('Got unexpected field names: %r' % kwds.keys())
        return result

    def __getnewargs__(self):
        'Return self as a plain tuple.  Used by copy and pickle.'
        return tuple(self)

    authdb = _property(_itemgetter(0), doc='Alias for field number 0')

    attrs = _property(_itemgetter(1), doc='Alias for field number 1')

    enabled = _property(_itemgetter(2), doc='Alias for field number 2')

    enabled_default = _property(_itemgetter(3), doc='Alias for field number 3')


[2018-12-27 17:06:27 +0000] [114000] [INFO] Booting worker with pid: 114000
[2018-12-27 17:06:27 EST] [114000] [INFO] MMLogger started
/opt/minemeld/engine/core/minemeld/flask/aaa.py:21: ExtDeprecationWarning: Importing flask.ext.login is deprecated, use flask_login instead.
  import flask.ext.login
[2018-12-27 17:06:28 EST] [114000] [INFO] Config loaded: {'MINEMELD_LOCAL_LIBRARY_PATH': '/opt/minemeld/local/library', 'USERS_DB': 'wsgi.htpasswd', 'MINEMELD_LOCAL_PROTOTYPE_PATH': '/opt/minemeld/local/prototypes', 'SUPERVISOR_URL': 'unix:///var/run/minemeld/minemeld.sock', 'MINEMELD_PROTOTYPE_PATH': '/opt/minemeld/local/prototypes:/opt/minemeld/prototypes/current', 'MINEMELD_PIP_PATH': '/opt/minemeld/engine/current/bin/pip', 'MINEMELD_TRACED_PURGE_PATH': '/opt/minemeld/engine/current/bin/mm-traced-purge', 'API_AUTH_ENABLED': True, 'MINEMELD_LOG_DIRECTORY_PATH': '/opt/minemeld/log', 'MINEMELD_7Z_PATH': '/usr/bin/7z', 'MINEMELD_LOCAL_PATH': '/opt/minemeld/local', 'MINEMELD_GIT_PATH': '/usr/bin/git', 'SNS_ENABLED': True}
[2018-12-27 17:06:28 EST] [114000] [INFO] USERS_DB loaded from /opt/minemeld/local/config/api/wsgi.htpasswd
[2018-12-27 17:06:28 EST] [114000] [INFO] FEEDS_USERS_DB loaded from /opt/minemeld/local/config/api/feeds.htpasswd
[2018-12-27 17:06:28 EST] [114000] [DEBUG] Instance uuid = 104b3c2daef742789a8f636334d64d3f
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/supervisor/minemeld-engine/restart' (HEAD, OPTIONS, GET) -> supervisor.restart_minemeld_engine>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/supervisor/minemeld-engine/start' (HEAD, OPTIONS, GET) -> supervisor.start_minemeld_engine>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/supervisor/minemeld-engine/stop' (HEAD, OPTIONS, GET) -> supervisor.stop_minemeld_engine>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/supervisor/minemeld-web/hup' (HEAD, OPTIONS, GET) -> supervisor.hup_minemeld_web>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/events/status' (HEAD, OPTIONS, GET) -> status.get_status_events>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/backup/import' (POST, OPTIONS) -> status.import_local_backup>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/aaa/users/current' (HEAD, OPTIONS, GET) -> aaa.get_current_user>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/extensions/git-install' (POST, OPTIONS) -> extensions.install_from_git>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/extensions/git-refs' (HEAD, OPTIONS, GET) -> extensions.get_git_refs>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/validate/syslogminerrule' (POST, OPTIONS) -> validate.validate_syslogminerrule>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/metrics/minemeld' (HEAD, OPTIONS, GET) -> metrics.get_global_metrics>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/committed' (HEAD, OPTIONS, GET) -> config.get_committed_config>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/traced/purge-all' (HEAD, OPTIONS, GET) -> traced.traced_purge_all>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/minemeld' (HEAD, OPTIONS, GET) -> status.get_minemeld_status>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/running' (HEAD, OPTIONS, GET) -> config.get_running_config>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/mgmtbus' (HEAD, OPTIONS, GET) -> config.get_mgmtbus>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/system' (HEAD, OPTIONS, GET) -> status.get_system_status>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/config' (HEAD, OPTIONS, GET) -> status.get_minemeld_running_config>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/backup' (POST, OPTIONS) -> status.generate_local_backup>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/mkwish' (POST, OPTIONS) -> status.sns_wish>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/reload' (HEAD, OPTIONS, GET) -> config.reload_running_config>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/commit' (POST, OPTIONS) -> config.commit>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/fabric' (HEAD, OPTIONS, GET) -> config.get_fabric>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/traced/query' (HEAD, OPTIONS, GET) -> traced.traced_query>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/info' (HEAD, OPTIONS, GET) -> status.get_system_info>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/info' (HEAD, OPTIONS, GET) -> config.get_config_info>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/full' (HEAD, OPTIONS, GET) -> config.get_config_full>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/node' (POST, OPTIONS) -> config.create_node>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/logs/minemeld-engine.log' (HEAD, OPTIONS, GET) -> logs.get_minemeld_engine_log>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/logs/minemeld-web.log' (HEAD, OPTIONS, GET) -> logs.get_minemeld_web_log>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/aaa/feeds' (HEAD, OPTIONS, GET) -> aaa.get_feeds>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/aaa/tags' (HEAD, OPTIONS, GET) -> aaa.get_tags>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/taxii-collection-management-service' (POST, OPTIONS) -> taxiicollmgmt.taxii_collection_mgmt_service>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/taxii-discovery-service' (POST, OPTIONS) -> taxiidiscovery.taxii_discovery_service>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/taxii-poll-service' (POST, OPTIONS) -> taxiipoll.taxii_poll_service>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/supervisor' (HEAD, OPTIONS, GET) -> supervisor.service_status>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/extensions' (HEAD, OPTIONS, GET) -> extensions.list_extensions>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/extensions' (POST, OPTIONS) -> extensions.upload_extension>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/prototype' (HEAD, OPTIONS, GET) -> prototype.list_prototypes>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/metrics/' (HEAD, OPTIONS, GET) -> metrics.get_metrics>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/logout' (HEAD, OPTIONS, GET) -> login.logout>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/login' (HEAD, POST, OPTIONS, GET) -> login.login>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/backup/import/<backup_id>/restore' (POST, OPTIONS) -> status.restore_local_backup>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/aaa/users/<subsystem>/<username>/attributes' (POST, OPTIONS) -> aaa.set_user_attributes>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/events/query/<quuid>' (HEAD, OPTIONS, GET) -> status.get_query_events>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/traced/query/<query_uuid>/kill' (HEAD, OPTIONS, GET) -> traced.traced_kill_query>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/data/<datafilename>/append' (POST, OPTIONS) -> configdata.append_config_data>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/<nodename>/signal/<signalname>' (HEAD, POST, OPTIONS, GET) -> status.signal_node>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/jobs/<job_group>/<jobid>/log' (HEAD, OPTIONS, GET) -> jobs.get_job_log>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/aaa/feeds/<feedname>/attributes' (PUT, POST, OPTIONS) -> aaa.set_feed_attributes>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/aaa/users/<subsystem>/<username>' (PUT, OPTIONS) -> aaa.set_user_password>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/aaa/users/<subsystem>/<username>' (OPTIONS, DELETE) -> aaa.delete_user>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/extensions/<extension>/deactivate' (HEAD, POST, OPTIONS, GET) -> extensions.deactivate_extension>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/extensions/<extension>/uninstall' (HEAD, POST, OPTIONS, GET) -> extensions.uninstall_extension>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/extensions/<extension>/activate' (POST, OPTIONS) -> extensions.activate_extension>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/metrics/minemeld/<nodetype>' (HEAD, OPTIONS, GET) -> metrics.get_node_type_metrics>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/metrics/<node>/<metric>' (HEAD, OPTIONS, GET) -> metrics.get_metric>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/backup/<jobid>' (HEAD, OPTIONS, GET) -> status.get_local_backup>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/node/<nodenum>' (HEAD, OPTIONS, GET) -> config.get_node>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/node/<nodenum>' (PUT, OPTIONS) -> config.set_node>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/node/<nodenum>' (OPTIONS, DELETE) -> config.delete_node>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/data/<datafilename>' (HEAD, OPTIONS, GET) -> configdata.get_config_data>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/config/data/<datafilename>' (PUT, OPTIONS) -> configdata.save_config_data>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/status/<nodename>/hup' (HEAD, POST, OPTIONS, GET) -> status.hup_node>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/jobs/<job_group>/<jobid>' (HEAD, OPTIONS, GET) -> jobs.get_job>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/aaa/users/<subsystem>' (HEAD, OPTIONS, GET) -> aaa.get_users>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/aaa/feeds/<feedname>' (OPTIONS, DELETE) -> aaa.delete_feed>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/prototype/<prototypename>' (HEAD, OPTIONS, GET) -> prototype.get_prototype>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/prototype/<prototypename>' (POST, OPTIONS) -> prototype.add_local_prototype>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/prototype/<prototypename>' (OPTIONS, DELETE) -> prototype.delete_local_prototype>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/metrics/<node>' (HEAD, OPTIONS, GET) -> metrics.get_node_metrics>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/static/<filename>' (HEAD, OPTIONS, GET) -> static>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/feeds/<feed>' (HEAD, OPTIONS, GET) -> feeds.get_feed_content>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] app rule: <Rule '/jobs/<job_group>' (HEAD, OPTIONS, GET) -> jobs.get_jobs>
[2018-12-27 17:06:29 EST] [114000] [DEBUG] redis session connection pool: in use: 0 available: 0
[2018-12-27 17:06:29 EST] [114000] [DEBUG] redis session connection pool: in use: 1 available: 0
[2018-12-27 17:06:29 EST] [114000] [DEBUG] redis session connection pool: in use: 2 available: 0
[2018-12-27 17:06:29 EST] [114000] [INFO] lock set 3b0bc1f7-a8c3-467d-8cc1-a52171a10bf5
127.0.0

@ 

[rmosquera]

Hi, I'm having the same problem, did you manage to find a solution?