st2api start keep doing Registering exchanges without errors.

[zhangqx2010]

SUMMARY

st2api start keep doing Registering exchanges without errors. The api service doesn't work.

ISSUE TYPE

• Bug Report

STACKSTORM VERSION

Paste the output of st2 --version:
st2 2.10.1, on Python 2.7.5

OS / ENVIRONMENT / INSTALL METHOD

Red Hat Enterprise Linux Server release 7.2 (Maipo)

STEPS TO REPRODUCE

I followed the ha doc.
During fresh install, api service started and listening on 9101 while the service actually doesn't work.
After open debug log, I use st2ctl start and st2ctl reload --verbose command.
And the /var/log/st2/st2api.log shows:

2019-01-22 16:59:05,906 139748641817296 DEBUG bootstrap_utils [-] Registering exchanges...
2019-01-22 16:59:34,004 139748856407872 INFO app [-] Creating st2api: StackStorm v2.10.1 as OpenAPI app.
2019-01-22 16:59:34,050 139748641817296 INFO __init__ [-] Connecting to database "st2" @ "stackstorm-controller:27017" as user "None".
2019-01-22 16:59:34,056 139748641817296 INFO __init__ [-] Successfully connected to database "st2" @ "stackstorm-controller:27017" as user "None".
2019-01-22 16:59:34,056 139748641817296 DEBUG __init__ [-] Ensuring database indexes...
2019-01-22 16:59:34,167 139748641817296 DEBUG __init__ [-] Skipping index cleanup for blacklisted model "PermissionGrantDB"...
2019-01-22 16:59:34,221 139748641817296 DEBUG __init__ [-] Indexes are ensured for models: ActionAliasDB, ActionAliasDB, ActionDB, ActionExecutionDB, ActionExecutionDB, ActionExecutionOutputDB, ActionExecutionSchedulingQueueItemDB, ActionExecutionStateDB, ActionExecutionStateDB, ApiKeyDB, ConfigDB, ConfigSchemaDB, GroupToRoleMappingDB, KeyValuePairDB, LiveActionDB, LiveActionDB, PackDB, PermissionGrantDB, PolicyDB, PolicyTypeDB, RoleDB, RuleDB, RuleEnforcementDB, RunnerTypeDB, RunnerTypeDB, SensorTypeDB, TaskExecutionDB, TokenDB, TraceDB, TriggerDB, TriggerInstanceDB, TriggerTypeDB, UserDB, UserRoleAssignmentDB, WorkflowExecutionDB
2019-01-22 16:59:34,221 139748641817296 DEBUG bootstrap_utils [-] Registering exchanges...
2019-01-22 17:00:04,174 139748856407872 INFO app [-] Creating st2api: StackStorm v2.10.1 as OpenAPI app.
2019-01-22 17:00:04,221 139748641817296 INFO __init__ [-] Connecting to database "st2" @ "stackstorm-controller:27017" as user "None".
2019-01-22 17:00:04,226 139748641817296 INFO __init__ [-] Successfully connected to database "st2" @ "stackstorm-controller:27017" as user "None".
2019-01-22 17:00:04,227 139748641817296 DEBUG __init__ [-] Ensuring database indexes...
2019-01-22 17:00:04,338 139748641817296 DEBUG __init__ [-] Skipping index cleanup for blacklisted model "PermissionGrantDB"...
2019-01-22 17:00:04,390 139748641817296 DEBUG __init__ [-] Indexes are ensured for models: ActionAliasDB, ActionAliasDB, ActionDB, ActionExecutionDB, ActionExecutionDB, ActionExecutionOutputDB, ActionExecutionSchedulingQueueItemDB, ActionExecutionStateDB, ActionExecutionStateDB, ApiKeyDB, ConfigDB, ConfigSchemaDB, GroupToRoleMappingDB, KeyValuePairDB, LiveActionDB, LiveActionDB, PackDB, PermissionGrantDB, PolicyDB, PolicyTypeDB, RoleDB, RuleDB, RuleEnforcementDB, RunnerTypeDB, RunnerTypeDB, SensorTypeDB, TaskExecutionDB, TokenDB, TraceDB, TriggerDB, TriggerInstanceDB, TriggerTypeDB, UserDB, UserRoleAssignmentDB, WorkflowExecutionDB
2019-01-22 17:00:04,391 139748641817296 DEBUG bootstrap_utils [-] Registering exchanges...
2019-01-22 17:00:34,348 139748856407872 INFO app [-] Creating st2api: StackStorm v2.10.1 as OpenAPI app.
2019-01-22 17:00:34,394 139748641817296 INFO __init__ [-] Connecting to database "st2" @ "stackstorm-controller:27017" as user "None".
2019-01-22 17:00:34,399 139748641817296 INFO __init__ [-] Successfully connected to database "st2" @ "stackstorm-controller:27017" as user "None".
2019-01-22 17:00:34,400 139748641817296 DEBUG __init__ [-] Ensuring database indexes...
2019-01-22 17:00:34,510 139748641817296 DEBUG __init__ [-] Skipping index cleanup for blacklisted model "PermissionGrantDB"...
2019-01-22 17:00:34,563 139748641817296 DEBUG __init__ [-] Indexes are ensured for models: ActionAliasDB, ActionAliasDB, ActionDB, ActionExecutionDB, ActionExecutionDB, ActionExecutionOutputDB, ActionExecutionSchedulingQueueItemDB, ActionExecutionStateDB, ActionExecutionStateDB, ApiKeyDB, ConfigDB, ConfigSchemaDB, GroupToRoleMappingDB, KeyValuePairDB, LiveActionDB, LiveActionDB, PackDB, PermissionGrantDB, PolicyDB, PolicyTypeDB, RoleDB, RuleDB, RuleEnforcementDB, RunnerTypeDB, RunnerTypeDB, SensorTypeDB, TaskExecutionDB, TokenDB, TraceDB, TriggerDB, TriggerInstanceDB, TriggerTypeDB, UserDB, UserRoleAssignmentDB, WorkflowExecutionDB
2019-01-22 17:00:34,564 139748641817296 DEBUG bootstrap_utils [-] Registering exchanges...
2019-01-22 17:01:04,505 139748856407872 INFO app [-] Creating st2api: StackStorm v2.10.1 as OpenAPI app.
2019-01-22 17:01:04,552 139748641817296 INFO __init__ [-] Connecting to database "st2" @ "stackstorm-controller:27017" as user "None".
2019-01-22 17:01:04,557 139748641817296 INFO __init__ [-] Successfully connected to database "st2" @ "stackstorm-controller:27017" as user "None".
2019-01-22 17:01:04,558 139748641817296 DEBUG __init__ [-] Ensuring database indexes...
2019-01-22 17:01:04,669 139748641817296 DEBUG __init__ [-] Skipping index cleanup for blacklisted model "PermissionGrantDB"...
2019-01-22 17:01:04,723 139748641817296 DEBUG __init__ [-] Indexes are ensured for models: ActionAliasDB, ActionAliasDB, ActionDB, ActionExecutionDB, ActionExecutionDB, ActionExecutionOutputDB, ActionExecutionSchedulingQueueItemDB, ActionExecutionStateDB, ActionExecutionStateDB, ApiKeyDB, ConfigDB, ConfigSchemaDB, GroupToRoleMappingDB, KeyValuePairDB, LiveActionDB, LiveActionDB, PackDB, PermissionGrantDB, PolicyDB, PolicyTypeDB, RoleDB, RuleDB, RuleEnforcementDB, RunnerTypeDB, RunnerTypeDB, SensorTypeDB, TaskExecutionDB, TokenDB, TraceDB, TriggerDB, TriggerInstanceDB, TriggerTypeDB, UserDB, UserRoleAssignmentDB, WorkflowExecutionDB
2019-01-22 17:01:04,724 139748641817296 DEBUG bootstrap_utils [-] Registering exchanges...

EXPECTED RESULTS

Api service start working.

ACTUAL RESULTS

api service doesn't work

 st2ctl status
##### st2 components status #####
st2actionrunner PID: 6088
st2actionrunner PID: 6090
st2actionrunner PID: 6092
st2actionrunner PID: 6094
st2actionrunner PID: 6096
st2actionrunner PID: 6098
st2actionrunner PID: 6100
st2actionrunner PID: 6102
st2actionrunner PID: 6104
st2actionrunner PID: 6106
st2api PID: 6125
st2api PID: 9140
st2stream PID: 6143
st2stream PID: 9145
st2auth PID: 6177
st2auth PID: 6354
st2garbagecollector PID: 6208
st2notifier PID: 6231
st2resultstracker PID: 6246
st2rulesengine PID: 6258
st2sensorcontainer PID: 6272
st2chatops is not running.
st2timersengine PID: 6304
st2workflowengine PID: 6323
st2scheduler PID: 6338
mistral-server PID: 6361
mistral.api PID: 6360
mistral.api PID: 6531
mistral.api PID: 6532

Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
tcp        0      0 127.0.0.1:9100          0.0.0.0:*               LISTEN      1/systemd
tcp        1      0 127.0.0.1:9101          0.0.0.0:*               LISTEN      1/systemd
tcp        0      0 127.0.0.1:9102          0.0.0.0:*               LISTEN      1/systemd
tcp        0      0 0.0.0.0:80              0.0.0.0:*               LISTEN      13452/nginx: master
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      1009/sshd
tcp        0      0 0.0.0.0:443             0.0.0.0:*               LISTEN      13452/nginx: master
tcp        0      0 127.0.0.1:8989          0.0.0.0:*               LISTEN      6360/python
tcp        0      0 0.0.0.0:10050           0.0.0.0:*               LISTEN      1019/zabbix_agentd
tcp6       0      0 :::22                   :::*                    LISTEN      1009/sshd
tcp6       0      0 :::10050                :::*                    LISTEN      1019/zabbix_agentd

[Kami]

I haven't seen this issue before, but I wonder if it's related to see build failures we were seeing on RHEL 6 recently (but not RHEL 7) which #4507 is supposed to fix.

It looks like the code hits retry when trying to register exchange / talk to RabbitMQ and restarts, but we never log the error.

I added a change in #4505 which updates out connection retry logic to log a message in case of an error. This should help with this issue.

[Kami]

I opened a PR #4509 which should help us give more insight in such issues once that change is merged and released.

[Kami]

@zhangqx2010 In the mean time, you can manually apply change from #4509 on your installation (files should be in /opt/stackstorm/st2/lib/python2.7/site-packages) and restart all the services.

This should give us more insight on what is going on (I would imagine RabbitMQ is not running or similar).

[zhangqx2010]

@Kami Yes, solved by starting RabbbitMQ service. The right logging error will be more helpful.
Thanks for quick response. I think I can close this issue now. 😄