Bug 1388188

Summary: puma server crashing?
Product: Red Hat CloudForms Management Engine Reporter: Dave Johnson <dajohnso>
Component: ApplianceAssignee: Joe Rafaniello <jrafanie>
Status: CLOSED WORKSFORME QA Contact: Dave Johnson <dajohnso>
Severity: high Docs Contact:
Priority: unspecified    
Version: 5.7.0CC: abellott, cpelland, dajohnso, jhardy, obarenbo, simaishi
Target Milestone: GAFlags: jrafanie: needinfo? (dajohnso)
jrafanie: needinfo? (dajohnso)
Target Release: cfme-future   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard: appliance
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-11-15 15:12:25 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: CFME Core Target Upstream Version:

Description Dave Johnson 2016-10-24 17:12:27 UTC
Description of problem:
==============================
Test automation is randomly getting failures in the web ui that look like a blank page with a sentence in the top left saying an unexpected lowlevel error occurred.  

Checking the production log, it looks like the puma server is crashing? on the back end (or gets a corrupted thread?), see the log snippet below.


Version-Release number of selected component (if applicable):
================================
5.7.0.6


How reproducible:
=======================
15%


Steps to Reproduce:
==========================
1.   None, its random
2.
3.


Additional info:


[----] I, [2016-10-24T00:16:50.462663 #16705:1543f20]  INFO -- : Started POST "/ems_infra" for 127.0.0.1 at 2016-10-24 00:16:50 -0400
[----] I, [2016-10-24T00:16:50.463914 #16705:1543f20]  INFO -- : Processing by EmsInfraController#create as */*
[----] I, [2016-10-24T00:16:50.464041 #16705:1543f20]  INFO -- :   Parameters: {"utf8"=>"✓", "authenticity_token"=>"StixJZFSpKzdmEPY8dNZiIw7LxWLoY2BDv0xWY65IC/lBFFJLFjjAsadMPa6LZZ8hhbZFKKbNgu6DyvD7Fdirw==", "button"=>"add", "cred_type"=>"metrics", "name"=>"rhv40", "emstype"=>"rhevm", "zone"=>"default", "default_userid"=>"admin@internal", "default_password"=>"[FILTERED]", "default_verify"=>"[FILTERED]", "default_auth_status"=>"on", "default_hostname"=>"[FILTERED]", "default_api_port"=>"", "metrics_hostname"=>"[FILTERED]", "metrics_api_port"=>"5432", "metrics_userid"=>"ovirt_engine_history", "metrics_password"=>"[FILTERED]", "metrics_verify"=>"[FILTERED]", "metrics_auth_status"=>"on"}
[----] I, [2016-10-24T00:16:50.590000 #16705:1543f20]  INFO -- : Completed 200 OK in 126ms (Views: 1.2ms | ActiveRecord: 0.0ms)
[----] I, [2016-10-24T00:16:51.141925 #16705:15425bc]  INFO -- : Started GET "/favicon.ico" for 127.0.0.1 at 2016-10-24 00:16:51 -0400
[----] F, [2016-10-24T00:16:51.147265 #16705:15425bc] FATAL -- :
[----] F, [2016-10-24T00:16:51.147338 #16705:15425bc] FATAL -- : ActionController::RoutingError (No route matches [GET] "/favicon.ico"):
[----] F, [2016-10-24T00:16:51.147387 #16705:15425bc] FATAL -- :
[----] F, [2016-10-24T00:16:51.147430 #16705:15425bc] FATAL -- : actionpack (5.0.0.1) lib/action_dispatch/middleware/debug_exceptions.rb:53:in `call'
[----] F, [2016-10-24T00:16:51.147469 #16705:15425bc] FATAL -- : actionpack (5.0.0.1) lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
[----] F, [2016-10-24T00:16:51.147506 #16705:15425bc] FATAL -- : railties (5.0.0.1) lib/rails/rack/logger.rb:36:in `call_app'
[----] F, [2016-10-24T00:16:51.147542 #16705:15425bc] FATAL -- : railties (5.0.0.1) lib/rails/rack/logger.rb:26:in `call'
[----] F, [2016-10-24T00:16:51.147578 #16705:15425bc] FATAL -- : request_store (1.3.1) lib/request_store/middleware.rb:9:in `call'
[----] F, [2016-10-24T00:16:51.147614 #16705:15425bc] FATAL -- : actionpack (5.0.0.1) lib/action_dispatch/middleware/request_id.rb:24:in `call'
[----] F, [2016-10-24T00:16:51.147650 #16705:15425bc] FATAL -- : rack (2.0.1) lib/rack/method_override.rb:22:in `call'
[----] F, [2016-10-24T00:16:51.147700 #16705:15425bc] FATAL -- : rack (2.0.1) lib/rack/runtime.rb:22:in `call'
[----] F, [2016-10-24T00:16:51.147750 #16705:15425bc] FATAL -- : activesupport (5.0.0.1) lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
[----] F, [2016-10-24T00:16:51.147789 #16705:15425bc] FATAL -- : actionpack (5.0.0.1) lib/action_dispatch/middleware/executor.rb:12:in `call'
[----] F, [2016-10-24T00:16:51.147826 #16705:15425bc] FATAL -- : rack (2.0.1) lib/rack/sendfile.rb:111:in `call'
[----] F, [2016-10-24T00:16:51.147862 #16705:15425bc] FATAL -- : railties (5.0.0.1) lib/rails/engine.rb:522:in `call'
[----] F, [2016-10-24T00:16:51.147928 #16705:15425bc] FATAL -- : puma (3.3.0) lib/puma/configuration.rb:224:in `call'
[----] F, [2016-10-24T00:16:51.147968 #16705:15425bc] FATAL -- : puma (3.3.0) lib/puma/server.rb:561:in `handle_request'
[----] F, [2016-10-24T00:16:51.148005 #16705:15425bc] FATAL -- : puma (3.3.0) lib/puma/server.rb:406:in `process_client'
[----] F, [2016-10-24T00:16:51.148042 #16705:15425bc] FATAL -- : puma (3.3.0) lib/puma/server.rb:271:in `block in run'
[----] F, [2016-10-24T00:16:51.148078 #16705:15425bc] FATAL -- : puma (3.3.0) lib/puma/thread_pool.rb:111:in `call'
[----] F, [2016-10-24T00:16:51.148113 #16705:15425bc] FATAL -- : puma (3.3.0) lib/puma/thread_pool.rb:111:in `block in spawn_thread'
[----] F, [2016-10-24T00:16:51.148149 #16705:15425bc] FATAL -- : logging (2.1.0) lib/logging/diagnostic_context.rb:450:in `call'
[----] F, [2016-10-24T00:16:51.148224 #16705:15425bc] FATAL -- : logging (2.1.0) lib/logging/diagnostic_context.rb:450:in `block in create_with_logging_context'

Comment 1 Gregg Tanzillo 2016-10-27 14:23:59 UTC
Joe, can you please look in to this? Thanks

Comment 2 Joe Rafaniello 2016-10-27 15:23:44 UTC
Hi Dave,

Can you please provide the evm.log and production.log when this happens?  Or point me at an appliance for me to look at.  I don't know why a missing route would cause the process to die.

How often does this happen?

Maybe it would be helpful to enable rails debug logging in the advanced setting in case it's a database connection issue:

Change:
 :level_rails: info

To:
 :level_rails: debug


Then, wait until `tail -f log/production.log` starts showing debug messages.

thanks

Comment 4 Dave Johnson 2016-11-15 15:12:25 UTC
So we can't reproduce this, even on the build where we originally had multiple people hitting it, closing for now until we see it again.