Bug 914838 - supervisor_log has debug enabled and grows very quickly
Summary: supervisor_log has debug enabled and grows very quickly
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: OKD
Classification: Red Hat
Component: Containers
Version: 2.x
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: ---
: ---
Assignee: Mrunal Patel
QA Contact: libra bugs
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2013-02-22 22:42 UTC by Matt Woodson
Modified: 2015-05-14 23:05 UTC (History)
2 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-03-15 14:00:44 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
supervisor_log-2-26-am.gz (29.90 KB, application/x-gzip)
2013-02-26 16:39 UTC, Matt Woodson
no flags Details
node supervisor log (332.25 KB, application/octet-stream)
2013-03-01 19:30 UTC, Brett Lentz
no flags Details
supervisor logs from stg node (316.06 KB, application/octet-stream)
2013-03-01 19:47 UTC, Brett Lentz
no flags Details
routes.json from node (15.61 KB, text/plain)
2013-03-01 20:35 UTC, Brett Lentz
no flags Details
routes.json from node (9.16 KB, application/x-bzip)
2013-03-01 20:51 UTC, Brett Lentz
no flags Details

Description Matt Woodson 2013-02-22 22:42:45 UTC
Description of problem:

/var/log/node-web-proxy/supervisor_log is growing out of control.   It appears to have DEBUG enabled AND it's not being rotated.

On one of our nodes, it's at 4.5GB and growing.  Here is an excerpt. 

====================================================
DEBUG: TypeError: Cannot call method 'split' of undefined
    at _get_routing_key (/usr/lib/node_modules/openshift-node-web-proxy/lib/proxy/ProxyRoutes.js:66:35)
    at ProxyRoutes.add (/usr/lib/node_modules/openshift-node-web-proxy/lib/proxy/ProxyRoutes.js:160:14)
    at ProxyRoutes.load (/usr/lib/node_modules/openshift-node-web-proxy/lib/proxy/ProxyRoutes.js:222:10)
    at /usr/lib/node_modules/openshift-node-web-proxy/lib/proxy/ProxyServer.js:721:44
    at Array.forEach (native)
    at /usr/lib/node_modules/openshift-node-web-proxy/lib/proxy/ProxyServer.js:721:17
    at /usr/lib/node_modules/openshift-node-web-proxy/lib/proxy/ProxyServer.js:452:14
    at ChildProcess.exithandler (child_process.js:276:7)
    at ChildProcess.emit (events.js:70:17)
    at maybeExit (child_process.js:358:16)

DEBUG: Program node /usr/lib/node_modules/openshift-node-web-proxy/bin/web-proxy.js --config /etc/openshift/web-proxy-config.json exited with code 1

DEBUG: Starting child process with 'node /usr/lib/node_modules/openshift-node-web-proxy/bin/web-proxy.js --config /etc/openshift/web-proxy-config.json'
1360684772452:INFO:[12/Feb/2013:10:59:32 -0500] - ProxyServer using config '/etc/openshift/web-proxy-config.json'
1360684772465:INFO:[12/Feb/2013:10:59:32 -0500] - Initializing ProxyServer ... 
1360684772467:INFO:[12/Feb/2013:10:59:32 -0500] - Stopping protocol servers for: 
1360684772478:INFO:[12/Feb/2013:10:59:32 -0500] - Creating protocol server for nonsecure_http_proxy
1360684772479:INFO:[12/Feb/2013:10:59:32 -0500] - Creating websocket server for nonsecure_http_proxy
1360684772481:INFO:[12/Feb/2013:10:59:32 -0500] - Creating protocol server for secure_http_proxy
1360684772522:INFO:[12/Feb/2013:10:59:32 -0500] - Creating websocket server for secure_http_proxy
1360684772523:INFO:[12/Feb/2013:10:59:32 -0500] - Initialized ProxyServer
1360684772523:INFO:[12/Feb/2013:10:59:32 -0500] - Starting protocol servers for: nonsecure_http_proxy,secure_http_proxy
1360684772523:INFO:[12/Feb/2013:10:59:32 -0500] - Starting protocol handler for nonsecure_http_proxy ...
1360684772524:INFO:[12/Feb/2013:10:59:32 -0500] - Starting protocol handler for secure_http_proxy ...
1360684772527:INFO:[12/Feb/2013:10:59:32 -0500] - secure_http_proxy listening on port 8000
1360684772528:INFO:[12/Feb/2013:10:59:32 -0500] - secure_http_proxy listening on port 8443
DEBUG: 

DEBUG: /usr/lib/node_modules/openshift-node-web-proxy/lib/proxy/ProxyRoutes.js:66

DEBUG:     zparts = zuri.split('://')[1].split('/');
============================================================================



Expected results:

This file should not being growing out of control like it does. 

DEBUG should be turned off for production environments

supervisor should setup a logrotate job to rotate this file

Comment 1 Rob Millner 2013-02-26 01:00:13 UTC
Passing to the resident NodeJS expert.

Comment 2 Mrunal Patel 2013-02-26 01:47:47 UTC
Matt,
The basic issue is that there is a failure in parsing some URIs.
We need to gather information about which URIs the proxy is failing to parse.

Could you turn on debugs using this command and gather a few logs?

kill -USR2 `cat /var/run/openshift-node-web-proxy.pid`

The same command could be used to turn them back off.

These debugs are different from the supervisor debugs that we see in the logs.

Thanks,
Mrunal

Comment 3 Matt Woodson 2013-02-26 16:37:59 UTC
I let this one run for about 5 minutes with the kill -USR2 `cat /var/run/openshift-node-web-proxy.pid` command enabled.

Can you tell me if this is what you are expecting to see?  If not, I will attempt it again.

Comment 4 Matt Woodson 2013-02-26 16:39:13 UTC
Created attachment 703019 [details]
supervisor_log-2-26-am.gz

here is log file

Comment 5 Brett Lentz 2013-03-01 19:30:32 UTC
Created attachment 704292 [details]
node supervisor log

Here's more logs.

Comment 6 Brett Lentz 2013-03-01 19:47:27 UTC
Created attachment 704296 [details]
supervisor logs from stg node

More supervisor logs.

Comment 7 Brett Lentz 2013-03-01 20:35:05 UTC
Created attachment 704311 [details]
routes.json from node

Here's the routes.json files from the node.

Comment 8 Brett Lentz 2013-03-01 20:51:18 UTC
Created attachment 704324 [details]
routes.json from node

Routes as separate files.

Comment 10 Mrunal Patel 2013-03-02 17:33:54 UTC
Creating an app name starting with http/https should not cause proxy to fail as in the logs above.

Comment 11 Meng Bo 2013-03-04 11:12:03 UTC
Checked on devenv_2890, 


1. tailf /var/log/node-web-proxy/supervisor_log
2. Create some apps 
3. Control and access the apps
4. Only few logs generated.

Mark bug as fixed.


# tailf /var/log/node-web-proxy/supervisor_log
1362395131036:INFO:[04/Mar/2013:06:05:31 -0500] - Routing information was reloaded
1362395178189:INFO:[04/Mar/2013:06:06:18 -0500] - Routing information was reloaded


Note You need to log in before you can comment on or make changes to this bug.