abonas
commented
8 years ago can you check the evm.log at the same point in time? what did the ui say - was there an error or it just didn't open completely?
Closed hhovsepy closed 5 years ago
abonas
commented
8 years ago can you check the evm.log at the same point in time? what did the ui say - was there an error or it just didn't open completely?
hhovsepy
commented
8 years ago UI did not open completely, with service temporary unavailable.
evm.log at that time contain this logs:
[----] I, [2016-08-09T04:14:58.316978 #3048:80f980] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-08-09T04:15:03.692580 #3048:80f980] INFO -- : MIQ(MiqQueue.put) Message id: [12570], id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-08-09T04:15:05.358063 #3048:80f980] INFO -- : MIQ(MiqQueue.put) Message id: [12571], id: [], Zone: [default], Role: [], Server: [dad4f6a0-5b9d-11e6-9563-fa163ee54d96], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-08-09T04:15:13.178492 #3091:1200d90] INFO -- : MIQ(MiqQueue.put) Message id: [12572], id: [], Zone: [default], Role: [ems_inventory], Server: [], Ident: [ems_2], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [[["ManageIQ::Providers::Hawkular::MiddlewareManager", 2]]]
[----] I, [2016-08-09T04:15:16.531007 #3091:1200d90] INFO -- : <AuditSuccess> MIQ(EmsCommon.process_emss) userid: [admin] - 'refresh_ems' successfully initiated for 1 Middleware Providers
[----] I, [2016-08-09T04:15:19.484061 #2832:80f980] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-08-09T04:15:19.488732 #2832:80f980] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=ems_2, wcount=2, priority=200
[----] I, [2016-08-09T04:15:19.488961 #2832:80f980] INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.0050356388092041016, :worker_monitor=>23.744043827056885, :worker_dequeue=>0.01598668098449707, :total_time=>23.765491724014282}
[----] I, [2016-08-09T04:15:19.764181 #2996:80f980] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [12570], MiqWorker id: [14], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [21.439205792] seconds
[----] I, [2016-08-09T04:15:19.764504 #2996:80f980] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [12570], Delivering...
[----] I, [2016-08-09T04:15:19.769818 #2996:80f980] INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0029854774475097656, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0030012130737304688, :pending_vm_jobs=>0.0006039142608642578, :vm_jobs_to_dispatch_count=>0, :total_time=>0.004817962646484375}
[----] I, [2016-08-09T04:15:19.770093 #2996:80f980] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [12570], State: [ok], Delivered in [0.005590606] seconds
[----] I, [2016-08-09T04:15:19.830629 #2996:80f980] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [12571], MiqWorker id: [14], Zone: [default], Role: [], Server: [dad4f6a0-5b9d-11e6-9563-fa163ee54d96], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [16.133403623] seconds
[----] I, [2016-08-09T04:15:19.830853 #2996:80f980] INFO -- : MIQ(MiqQueue#deliver) Message id: [12571], Delivering...
[----] I, [2016-08-09T04:15:19.841013 #2996:80f980] INFO -- : MIQ(MiqQueue#delivered) Message id: [12571], State: [ok], Delivered in [0.010130305] seconds
[----] I, [2016-08-09T04:15:20.379093 #3048:80f980] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-08-09T04:15:20.413657 #3048:80f980] INFO -- : MIQ(MiqQueue.put) Message id: [12573], id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-08-09T04:15:24.489466 #2832:80f980] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-08-09 08:15:24 UTC]...
[----] I, [2016-08-09T04:15:24.537902 #2832:80f980] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-08-09 08:15:24 UTC]...Complete@Fryguy any idea regarding the puma exception here? anything else you recommend to check?
hhovsepy
commented
7 years ago @pilhuhn @gtanzillo Still I see this issue on MiQ. Production log: production-log.txt
hhovsepy
commented
7 years ago hhovsepy
commented
7 years ago It happens when I add datasource and operation fails.
pilhuhn
commented
7 years ago @miq-bot assign @cfcosta Caina please have a look
cfcosta
commented
7 years ago On it.
cfcosta
commented
7 years ago Hello, @hhovsepy!
I did some research and tried to replicate your error locally with no success. Some resources point that this error is common on websocket connections/actioncable, and we did a change to increase the amount of database connections available for them. Given that your issue is older than this change, can you check if it was fixed by f85a88d3? It was applied on master on Nov 22, so it could be fixed already.
If not, is it possible for you to generate either a test case or a way to reliably replicate the bug? That'd make it a lot easier to fix.
abonas
commented
7 years ago abonas
commented
7 years ago given that it's an infra/core issue, reassigning. @miq-bot assign @blomquisg
jrafanie
commented
7 years ago @cfcosta @abonas In #14116 we tried to diagnose this but weren't provided information to work with. We need to see what is consuming database connections. If you can recreate this in production mode as the BZ says, enable the rails debug logging and see what is consuming the database connections. What actions checkout connections and don't return them? We can help track this down but honestly, I have no idea what environment is needed or how I can set it up to recreate it. It might be the actioncable stuff but we haven't done enough diagnostics to say whether this is true or not. I'm not sure @blomquisg will be able to help. Does this only happen on the middleware UI requests? If so, why?
blomquisg
commented
7 years ago Sorry this was off my radar entirely. We've seen issues with the bot not reassigning when it's supposed to. But, haven't figured out why that happens.
I reassigned to @gtanzillo to take a look. But, as @jrafanie said, it's hard to say if they can make any progress without some of the data he's looking for.
jrafanie
commented
7 years ago @cfcosta @abonas bump. Any update on this issue? How can I help? Can you provide logs in production mode on an appliance with rails debug logging enabled with the issue recreated as requested before?
abonas
commented
7 years ago @hhovsepy please see @jrafanie request regarding logs ^^
hhovsepy
commented
7 years ago @jrafanie I am running ManageIQ in a docker container, do you know how can I reload the log level configuration changes? I am changing 'config.log_level = :debug' in config/environments/production.rb but it still logs are in INFO level.
jrafanie
commented
7 years ago @hhovsepy go to configuration/advanced settings, change level_rails to debug. You should start seeing debug messages in log/production.log and can begin your recreation of the issue.
FYI, we've discussed more of this here
Once you get production.log showing these messages and recreate the issue, please provide the production.log and evm.log. Thank you.
hhovsepy
commented
7 years ago @jrafanie I was able to reproduce the issue with debug level of logs. But the messages you mentioned did not appear in logs.
The server becomes unavailable after this line in evm.log: [----] E, [2017-06-08T08:50:38.632768 #694:3f9bded11438] ERROR -- : MIQ(ManageIQ::Providers::Hawkular::MiddlewareManager#add_middleware_datasource) error callback was called, reason: Could not perform [Add] on a [Datasource] given by inventory path [/t;hawkular/f;ca4191af-e7fe-46a2-a968-d42939696443/r;EAP7~~] requested on [2017-06-08T08:50Z]: org.hawkular.dmr.api.OperationFailureException: Could not perform operation [composite]: {"WFLYCTL0062: Composite operation failed and was rolled back. Steps that failed:" => {"Operation step-1" => {"WFLYCTL0180: Services with missing/unavailable dependencies" => ["jboss.driver-demander.java:/MSSQLXADS is missing [jboss.jdbc-driver.sqlserver]","org.wildfly.data-source.MSSQLXADS is missing [jboss.jdbc-driver.sqlserver]"]}}}
jrafanie
commented
7 years ago Thanks @hhovsepy, this is exactly what we needed!
@skateman Can you review the production.txt attached above? It looks like actioncable threads are consuming db connections and never checking them back in.
Basically, I looked for all of the log_after lines to see when connections checkout and checkin and looked for thread ids where the check out occurs but the db connection is never checked in.
The following threads all never check in their database connection:
3f9bdcc28834
3f9bdedfbb14
3f9bdda5699c
3f9bde3a5c64
3f9bdf2bf024
3f9bdf11dd4c
3f9bded114381) Is this expected? It seems so but didn't we go through this process already of figuring out how many connections we need? 2) If so, how many threads per puma process are you expecting to be created and hold onto permanent db connections? 3) Why is this happening in around the POSTs "/middleware_server/add_datasource" and not other places? 4) we have ui, webservice and websocket workers with 8, 8, and 14 connections in the settings.yml, are these correct?
:ui_worker:
:connection_pool_size: 8
...
:web_service_worker:
:connection_pool_size: 8
...
:websocket_worker:
:connection_pool_size: 14grep -E "3f9bdcc28834|3f9bdedfbb14|3f9bdda5699c|3f9bde3a5c64|3f9bdf2bf024|3f9bdf11dd4c|3f9bded11438" production.txt
[----] D, [2017-06-08T08:48:53.801572 #694:3f9bdcc28834] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 8, connections: 3, in use: 3, waiting_in_queue: 0
[----] D, [2017-06-08T08:48:53.803671 #694:3f9bdcc28834] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Load (0.4ms) SELECT "middleware_servers".* FROM "middleware_servers" WHERE "middleware_servers"."ems_ref" = $1 LIMIT $2 [["ems_ref", "/t;hawkular/f;ca4191af-e7fe-46a2-a968-d42939696443/r;EAP7~~"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:48:53.834382 #694:3f9bdcc28834] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Inst Including Associations (30.2ms - 1rows)
[----] D, [2017-06-08T08:48:54.337733 #694:3f9bdcc28834] DEBUG -- : NotificationType Load (0.5ms) SELECT "notification_types".* FROM "notification_types" WHERE "notification_types"."name" = $1 LIMIT $2 [["name", "mw_op_failure"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:48:54.338252 #694:3f9bdcc28834] DEBUG -- : NotificationType Inst Including Associations (0.2ms - 1rows)
[----] D, [2017-06-08T08:48:54.341665 #694:3f9bdcc28834] DEBUG -- : (0.2ms) BEGIN
[----] D, [2017-06-08T08:48:54.343768 #694:3f9bdcc28834] DEBUG -- : (0.4ms) SELECT "users"."id" FROM "users"
[----] D, [2017-06-08T08:48:54.905757 #694:3f9bdcc28834] DEBUG -- : SQL (150.1ms) INSERT INTO "notifications" ("notification_type_id", "created_at", "updated_at", "options") VALUES ($1, $2, $3, $4) RETURNING "id" [["notification_type_id", 23], ["created_at", "2017-06-08 08:48:54.342314"], ["updated_at", "2017-06-08 08:48:54.342314"], ["options", "---\n:op_name: Add JDBC Driver\n:op_arg: mysql\n:mw_server: EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)\n"]]
[----] D, [2017-06-08T08:48:54.910237 #694:3f9bdcc28834] DEBUG -- : SQL (2.7ms) INSERT INTO "notification_recipients" ("notification_id", "user_id", "seen") VALUES ($1, $2, $3) RETURNING "id" [["notification_id", 1], ["user_id", 1], ["seen", "f"]]
[----] D, [2017-06-08T08:48:55.173904 #694:3f9bdcc28834] DEBUG -- : (262.4ms) COMMIT
[----] D, [2017-06-08T08:48:55.177281 #694:3f9bdcc28834] DEBUG -- : (0.4ms) SELECT "notification_recipients"."id", "notification_recipients"."user_id" FROM "notification_recipients" WHERE "notification_recipients"."notification_id" = $1 [["notification_id", 1]]
[----] I, [2017-06-08T08:48:55.219848 #694:3f9bdcc28834] INFO -- : [ActionCable] Broadcasting to notifications_1: {:level=>"warning", :created_at=>Thu, 08 Jun 2017 08:48:54 UTC +00:00, :text=>"The operation %{op_name} %{op_arg} on %{mw_server} has failed to complete. Please check the logs for further details.", :bindings=>{:op_name=>{:text=>"Add JDBC Driver"}, :op_arg=>{:text=>"mysql"}, :mw_server=>{:text=>"EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)"}}}
[----] D, [2017-06-08T08:49:20.528625 #694:3f9bdedfbb14] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 8, connections: 3, in use: 3, waiting_in_queue: 0
[----] D, [2017-06-08T08:49:20.529690 #694:3f9bdedfbb14] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Load (0.5ms) SELECT "middleware_servers".* FROM "middleware_servers" WHERE "middleware_servers"."ems_ref" = $1 LIMIT $2 [["ems_ref", "/t;hawkular/f;ca4191af-e7fe-46a2-a968-d42939696443/r;EAP7~~"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:49:20.530252 #694:3f9bdedfbb14] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Inst Including Associations (0.2ms - 1rows)
[----] D, [2017-06-08T08:49:20.590470 #694:3f9bdedfbb14] DEBUG -- : NotificationType Load (59.2ms) SELECT "notification_types".* FROM "notification_types" WHERE "notification_types"."name" = $1 LIMIT $2 [["name", "mw_op_failure"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:49:20.591185 #694:3f9bdedfbb14] DEBUG -- : NotificationType Inst Including Associations (0.2ms - 1rows)
[----] D, [2017-06-08T08:49:20.593259 #694:3f9bdedfbb14] DEBUG -- : (0.2ms) BEGIN
[----] D, [2017-06-08T08:49:20.595137 #694:3f9bdedfbb14] DEBUG -- : (0.3ms) SELECT "users"."id" FROM "users"
[----] D, [2017-06-08T08:49:20.618750 #694:3f9bdedfbb14] DEBUG -- : SQL (1.0ms) INSERT INTO "notifications" ("notification_type_id", "created_at", "updated_at", "options") VALUES ($1, $2, $3, $4) RETURNING "id" [["notification_type_id", 23], ["created_at", "2017-06-08 08:49:20.593963"], ["updated_at", "2017-06-08 08:49:20.593963"], ["options", "---\n:op_name: Add JDBC Driver\n:op_arg: oracle\n:mw_server: EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)\n"]]
[----] D, [2017-06-08T08:49:20.644755 #694:3f9bdedfbb14] DEBUG -- : SQL (24.7ms) INSERT INTO "notification_recipients" ("notification_id", "user_id", "seen") VALUES ($1, $2, $3) RETURNING "id" [["notification_id", 2], ["user_id", 1], ["seen", "f"]]
[----] D, [2017-06-08T08:49:20.685417 #694:3f9bdedfbb14] DEBUG -- : (39.3ms) COMMIT
[----] D, [2017-06-08T08:49:20.730847 #694:3f9bdedfbb14] DEBUG -- : (43.0ms) SELECT "notification_recipients"."id", "notification_recipients"."user_id" FROM "notification_recipients" WHERE "notification_recipients"."notification_id" = $1 [["notification_id", 2]]
[----] I, [2017-06-08T08:49:20.732233 #694:3f9bdedfbb14] INFO -- : [ActionCable] Broadcasting to notifications_1: {:level=>"warning", :created_at=>Thu, 08 Jun 2017 08:49:20 UTC +00:00, :text=>"The operation %{op_name} %{op_arg} on %{mw_server} has failed to complete. Please check the logs for further details.", :bindings=>{:op_name=>{:text=>"Add JDBC Driver"}, :op_arg=>{:text=>"oracle"}, :mw_server=>{:text=>"EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)"}}}
[----] D, [2017-06-08T08:49:41.474814 #694:3f9bdda5699c] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 8, connections: 4, in use: 4, waiting_in_queue: 0
[----] D, [2017-06-08T08:49:41.475833 #694:3f9bdda5699c] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Load (0.5ms) SELECT "middleware_servers".* FROM "middleware_servers" WHERE "middleware_servers"."ems_ref" = $1 LIMIT $2 [["ems_ref", "/t;hawkular/f;ca4191af-e7fe-46a2-a968-d42939696443/r;EAP7~~"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:49:41.476357 #694:3f9bdda5699c] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Inst Including Associations (0.2ms - 1rows)
[----] D, [2017-06-08T08:49:41.477954 #694:3f9bdda5699c] DEBUG -- : NotificationType Load (0.7ms) SELECT "notification_types".* FROM "notification_types" WHERE "notification_types"."name" = $1 LIMIT $2 [["name", "mw_op_success"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:49:41.478340 #694:3f9bdda5699c] DEBUG -- : NotificationType Inst Including Associations (0.1ms - 1rows)
[----] D, [2017-06-08T08:49:41.479941 #694:3f9bdda5699c] DEBUG -- : (0.2ms) BEGIN
[----] D, [2017-06-08T08:49:41.481482 #694:3f9bdda5699c] DEBUG -- : (0.3ms) SELECT "users"."id" FROM "users"
[----] D, [2017-06-08T08:49:41.485882 #694:3f9bdda5699c] DEBUG -- : SQL (0.8ms) INSERT INTO "notifications" ("notification_type_id", "created_at", "updated_at", "options") VALUES ($1, $2, $3, $4) RETURNING "id" [["notification_type_id", 22], ["created_at", "2017-06-08 08:49:41.480435"], ["updated_at", "2017-06-08 08:49:41.480435"], ["options", "---\n:op_name: Add Datasource\n:op_arg: PostgresXADS\n:mw_server: EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)\n"]]
[----] D, [2017-06-08T08:49:41.487784 #694:3f9bdda5699c] DEBUG -- : SQL (0.6ms) INSERT INTO "notification_recipients" ("notification_id", "user_id", "seen") VALUES ($1, $2, $3) RETURNING "id" [["notification_id", 3], ["user_id", 1], ["seen", "f"]]
[----] D, [2017-06-08T08:49:41.506508 #694:3f9bdda5699c] DEBUG -- : (17.9ms) COMMIT
[----] D, [2017-06-08T08:49:41.508463 #694:3f9bdda5699c] DEBUG -- : (0.3ms) SELECT "notification_recipients"."id", "notification_recipients"."user_id" FROM "notification_recipients" WHERE "notification_recipients"."notification_id" = $1 [["notification_id", 3]]
[----] I, [2017-06-08T08:49:41.509242 #694:3f9bdda5699c] INFO -- : [ActionCable] Broadcasting to notifications_1: {:level=>"success", :created_at=>Thu, 08 Jun 2017 08:49:41 UTC +00:00, :text=>"The operation %{op_name} %{op_arg} on %{mw_server} completed successfully.", :bindings=>{:op_name=>{:text=>"Add Datasource"}, :op_arg=>{:text=>"PostgresXADS"}, :mw_server=>{:text=>"EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)"}}}
[----] D, [2017-06-08T08:49:54.456706 #694:3f9bde3a5c64] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 8, connections: 5, in use: 5, waiting_in_queue: 0
[----] D, [2017-06-08T08:49:54.458193 #694:3f9bde3a5c64] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Load (1.0ms) SELECT "middleware_servers".* FROM "middleware_servers" WHERE "middleware_servers"."ems_ref" = $1 LIMIT $2 [["ems_ref", "/t;hawkular/f;ca4191af-e7fe-46a2-a968-d42939696443/r;EAP7~~"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:49:54.458829 #694:3f9bde3a5c64] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Inst Including Associations (0.3ms - 1rows)
[----] D, [2017-06-08T08:49:54.460340 #694:3f9bde3a5c64] DEBUG -- : NotificationType Load (0.6ms) SELECT "notification_types".* FROM "notification_types" WHERE "notification_types"."name" = $1 LIMIT $2 [["name", "mw_op_failure"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:49:54.460842 #694:3f9bde3a5c64] DEBUG -- : NotificationType Inst Including Associations (0.1ms - 1rows)
[----] D, [2017-06-08T08:49:54.462579 #694:3f9bde3a5c64] DEBUG -- : (0.2ms) BEGIN
[----] D, [2017-06-08T08:49:54.464188 #694:3f9bde3a5c64] DEBUG -- : (0.3ms) SELECT "users"."id" FROM "users"
[----] D, [2017-06-08T08:49:54.469583 #694:3f9bde3a5c64] DEBUG -- : SQL (0.9ms) INSERT INTO "notifications" ("notification_type_id", "created_at", "updated_at", "options") VALUES ($1, $2, $3, $4) RETURNING "id" [["notification_type_id", 23], ["created_at", "2017-06-08 08:49:54.463131"], ["updated_at", "2017-06-08 08:49:54.463131"], ["options", "---\n:op_name: Add Datasource\n:op_arg: PostgresDS\n:mw_server: EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)\n"]]
[----] D, [2017-06-08T08:49:54.472230 #694:3f9bde3a5c64] DEBUG -- : SQL (0.7ms) INSERT INTO "notification_recipients" ("notification_id", "user_id", "seen") VALUES ($1, $2, $3) RETURNING "id" [["notification_id", 4], ["user_id", 1], ["seen", "f"]]
[----] D, [2017-06-08T08:49:54.511536 #694:3f9bde3a5c64] DEBUG -- : (38.0ms) COMMIT
[----] D, [2017-06-08T08:49:54.514819 #694:3f9bde3a5c64] DEBUG -- : (0.5ms) SELECT "notification_recipients"."id", "notification_recipients"."user_id" FROM "notification_recipients" WHERE "notification_recipients"."notification_id" = $1 [["notification_id", 4]]
[----] I, [2017-06-08T08:49:54.516106 #694:3f9bde3a5c64] INFO -- : [ActionCable] Broadcasting to notifications_1: {:level=>"warning", :created_at=>Thu, 08 Jun 2017 08:49:54 UTC +00:00, :text=>"The operation %{op_name} %{op_arg} on %{mw_server} has failed to complete. Please check the logs for further details.", :bindings=>{:op_name=>{:text=>"Add Datasource"}, :op_arg=>{:text=>"PostgresDS"}, :mw_server=>{:text=>"EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)"}}}
[----] D, [2017-06-08T08:50:08.276522 #694:3f9bdf2bf024] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 8, connections: 7, in use: 7, waiting_in_queue: 0
[----] D, [2017-06-08T08:50:08.278766 #694:3f9bdf2bf024] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Load (1.6ms) SELECT "middleware_servers".* FROM "middleware_servers" WHERE "middleware_servers"."ems_ref" = $1 LIMIT $2 [["ems_ref", "/t;hawkular/f;ca4191af-e7fe-46a2-a968-d42939696443/r;EAP7~~"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:50:08.279693 #694:3f9bdf2bf024] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Inst Including Associations (0.3ms - 1rows)
[----] D, [2017-06-08T08:50:08.281717 #694:3f9bdf2bf024] DEBUG -- : NotificationType Load (0.8ms) SELECT "notification_types".* FROM "notification_types" WHERE "notification_types"."name" = $1 LIMIT $2 [["name", "mw_op_success"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:50:08.282339 #694:3f9bdf2bf024] DEBUG -- : NotificationType Inst Including Associations (0.2ms - 1rows)
[----] D, [2017-06-08T08:50:08.284827 #694:3f9bdf2bf024] DEBUG -- : (0.2ms) BEGIN
[----] D, [2017-06-08T08:50:08.287974 #694:3f9bdf2bf024] DEBUG -- : (1.1ms) SELECT "users"."id" FROM "users"
[----] D, [2017-06-08T08:50:08.292722 #694:3f9bdf2bf024] DEBUG -- : SQL (0.9ms) INSERT INTO "notifications" ("notification_type_id", "created_at", "updated_at", "options") VALUES ($1, $2, $3, $4) RETURNING "id" [["notification_type_id", 22], ["created_at", "2017-06-08 08:50:08.285651"], ["updated_at", "2017-06-08 08:50:08.285651"], ["options", "---\n:op_name: Add Datasource\n:op_arg: XAOracleDS\n:mw_server: EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)\n"]]
[----] D, [2017-06-08T08:50:08.294821 #694:3f9bdf2bf024] DEBUG -- : SQL (0.6ms) INSERT INTO "notification_recipients" ("notification_id", "user_id", "seen") VALUES ($1, $2, $3) RETURNING "id" [["notification_id", 5], ["user_id", 1], ["seen", "f"]]
[----] D, [2017-06-08T08:50:08.367816 #694:3f9bdf2bf024] DEBUG -- : (71.3ms) COMMIT
[----] D, [2017-06-08T08:50:08.371581 #694:3f9bdf2bf024] DEBUG -- : (0.4ms) SELECT "notification_recipients"."id", "notification_recipients"."user_id" FROM "notification_recipients" WHERE "notification_recipients"."notification_id" = $1 [["notification_id", 5]]
[----] I, [2017-06-08T08:50:08.372917 #694:3f9bdf2bf024] INFO -- : [ActionCable] Broadcasting to notifications_1: {:level=>"success", :created_at=>Thu, 08 Jun 2017 08:50:08 UTC +00:00, :text=>"The operation %{op_name} %{op_arg} on %{mw_server} completed successfully.", :bindings=>{:op_name=>{:text=>"Add Datasource"}, :op_arg=>{:text=>"XAOracleDS"}, :mw_server=>{:text=>"EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)"}}}
[----] D, [2017-06-08T08:50:24.682150 #694:3f9bdf11dd4c] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 8, connections: 7, in use: 7, waiting_in_queue: 0
[----] D, [2017-06-08T08:50:24.683466 #694:3f9bdf11dd4c] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Load (0.7ms) SELECT "middleware_servers".* FROM "middleware_servers" WHERE "middleware_servers"."ems_ref" = $1 LIMIT $2 [["ems_ref", "/t;hawkular/f;ca4191af-e7fe-46a2-a968-d42939696443/r;EAP7~~"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:50:24.684296 #694:3f9bdf11dd4c] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Inst Including Associations (0.3ms - 1rows)
[----] D, [2017-06-08T08:50:24.686342 #694:3f9bdf11dd4c] DEBUG -- : NotificationType Load (0.9ms) SELECT "notification_types".* FROM "notification_types" WHERE "notification_types"."name" = $1 LIMIT $2 [["name", "mw_op_success"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:50:24.687011 #694:3f9bdf11dd4c] DEBUG -- : NotificationType Inst Including Associations (0.2ms - 1rows)
[----] D, [2017-06-08T08:50:24.689843 #694:3f9bdf11dd4c] DEBUG -- : (0.8ms) BEGIN
[----] D, [2017-06-08T08:50:24.694206 #694:3f9bdf11dd4c] DEBUG -- : (2.4ms) SELECT "users"."id" FROM "users"
[----] D, [2017-06-08T08:50:24.699752 #694:3f9bdf11dd4c] DEBUG -- : SQL (0.8ms) INSERT INTO "notifications" ("notification_type_id", "created_at", "updated_at", "options") VALUES ($1, $2, $3, $4) RETURNING "id" [["notification_type_id", 22], ["created_at", "2017-06-08 08:50:24.690577"], ["updated_at", "2017-06-08 08:50:24.690577"], ["options", "---\n:op_name: Add Datasource\n:op_arg: OracleDS\n:mw_server: EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)\n"]]
[----] D, [2017-06-08T08:50:24.701666 #694:3f9bdf11dd4c] DEBUG -- : SQL (0.5ms) INSERT INTO "notification_recipients" ("notification_id", "user_id", "seen") VALUES ($1, $2, $3) RETURNING "id" [["notification_id", 6], ["user_id", 1], ["seen", "f"]]
[----] D, [2017-06-08T08:50:24.754390 #694:3f9bdf11dd4c] DEBUG -- : (51.6ms) COMMIT
[----] D, [2017-06-08T08:50:24.757088 #694:3f9bdf11dd4c] DEBUG -- : (0.4ms) SELECT "notification_recipients"."id", "notification_recipients"."user_id" FROM "notification_recipients" WHERE "notification_recipients"."notification_id" = $1 [["notification_id", 6]]
[----] I, [2017-06-08T08:50:24.758190 #694:3f9bdf11dd4c] INFO -- : [ActionCable] Broadcasting to notifications_1: {:level=>"success", :created_at=>Thu, 08 Jun 2017 08:50:24 UTC +00:00, :text=>"The operation %{op_name} %{op_arg} on %{mw_server} completed successfully.", :bindings=>{:op_name=>{:text=>"Add Datasource"}, :op_arg=>{:text=>"OracleDS"}, :mw_server=>{:text=>"EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)"}}}
[----] D, [2017-06-08T08:50:38.634225 #694:3f9bded11438] DEBUG -- : PostgreSQLAdapter#log_after_checkout, connection_pool: size: 8, connections: 8, in use: 8, waiting_in_queue: 0
[----] D, [2017-06-08T08:50:38.635366 #694:3f9bded11438] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Load (0.5ms) SELECT "middleware_servers".* FROM "middleware_servers" WHERE "middleware_servers"."ems_ref" = $1 LIMIT $2 [["ems_ref", "/t;hawkular/f;ca4191af-e7fe-46a2-a968-d42939696443/r;EAP7~~"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:50:38.636010 #694:3f9bded11438] DEBUG -- : ManageIQ::Providers::Hawkular::MiddlewareManager::MiddlewareServer Inst Including Associations (0.2ms - 1rows)
[----] D, [2017-06-08T08:50:38.637794 #694:3f9bded11438] DEBUG -- : NotificationType Load (0.9ms) SELECT "notification_types".* FROM "notification_types" WHERE "notification_types"."name" = $1 LIMIT $2 [["name", "mw_op_failure"], ["LIMIT", 1]]
[----] D, [2017-06-08T08:50:38.638161 #694:3f9bded11438] DEBUG -- : NotificationType Inst Including Associations (0.1ms - 1rows)
[----] D, [2017-06-08T08:50:38.639869 #694:3f9bded11438] DEBUG -- : (0.2ms) BEGIN
[----] D, [2017-06-08T08:50:38.641520 #694:3f9bded11438] DEBUG -- : (0.3ms) SELECT "users"."id" FROM "users"
[----] D, [2017-06-08T08:50:38.646117 #694:3f9bded11438] DEBUG -- : SQL (0.9ms) INSERT INTO "notifications" ("notification_type_id", "created_at", "updated_at", "options") VALUES ($1, $2, $3, $4) RETURNING "id" [["notification_type_id", 23], ["created_at", "2017-06-08 08:50:38.640340"], ["updated_at", "2017-06-08 08:50:38.640340"], ["options", "---\n:op_name: Add Datasource\n:op_arg: MSSQLXADS\n:mw_server: EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)\n"]]
[----] D, [2017-06-08T08:50:38.648056 #694:3f9bded11438] DEBUG -- : SQL (0.7ms) INSERT INTO "notification_recipients" ("notification_id", "user_id", "seen") VALUES ($1, $2, $3) RETURNING "id" [["notification_id", 7], ["user_id", 1], ["seen", "f"]]
[----] D, [2017-06-08T08:50:38.699452 #694:3f9bded11438] DEBUG -- : (50.5ms) COMMIT
[----] D, [2017-06-08T08:50:38.702233 #694:3f9bded11438] DEBUG -- : (0.4ms) SELECT "notification_recipients"."id", "notification_recipients"."user_id" FROM "notification_recipients" WHERE "notification_recipients"."notification_id" = $1 [["notification_id", 7]]
[----] I, [2017-06-08T08:50:38.703344 #694:3f9bded11438] INFO -- : [ActionCable] Broadcasting to notifications_1: {:level=>"warning", :created_at=>Thu, 08 Jun 2017 08:50:38 UTC +00:00, :text=>"The operation %{op_name} %{op_arg} on %{mw_server} has failed to complete. Please check the logs for further details.", :bindings=>{:op_name=>{:text=>"Add Datasource"}, :op_arg=>{:text=>"MSSQLXADS"}, :mw_server=>{:text=>"EAP7 (ca4191af-e7fe-46a2-a968-d42939696443)"}}}
skateman
commented
7 years ago @jrafanie I don't know that much about this, but AC is blocking the connection using the LISTEN command and it's possible that it's not going fully through AR (i.e. it leverages the credentials but nothing more). Due to the socket hijacking AC is quite isolated from Puma, I'm not sure how much, but it's possible that it needs its own. The one thing I'm sure about is that these are persistent as the LISTEN is a blocking call.
miq-bot
commented
6 years ago This issue has been automatically marked as stale because it has not been updated for at least 6 months.
If you can still reproduce this issue on the current release or on master, please reply with all of the information you have about it in order to keep the issue open.
Thank you for all your contributions!
JPrause
commented
5 years ago @hhovsepy it appears this issue can now be closed. If so, can you close. If there's no update by next week, I'll be closing this issue.
JPrause
commented
5 years ago Closing issue. If you feel the issue needs to remain open, please let me know and it will be reopened. @miq-bot close_issue
FATAL error in MiQ production.log and service was restarted.
Steps I did before were:
@abonas