Slow splunkweb startup caused by splunk_instrumentation

[carlalldis]

Hi,

After an upgrade from 6.3 to 6.6.1 I am experiencing very slow startups (around 5 minutes) on all search heads, indexers, heavy forwarder, license master and deployment server, while 'Waiting for web server at http://127.0.0.1:8000 to be available' . This also seems to be the case on a standalone dev instance.

I have tracked the issue down to splunk_instrumentation. See the large gap of time in web_service.log without debug logging:

2017-06-06 13:27:04,519 INFO    [59369f954b7fb8451b27d0] root:267 - Proxied mode ip_address=127.0.0.1 port=8065 exposed_port=8000:
2017-06-06 13:31:19,367 INFO    [59369f954b7fb8451b27d0] custom:211 - Registering custom app endpoint: splunk_instrumentation/instrumentation_controller
2017-06-06 13:31:19,454 INFO    [59369f954b7fb8451b27d0] custom:211 - Registering custom app endpoint: Splunk_TA_nix/setup

And with python debug logging on:

2017-06-06 13:40:04,899 INFO [5936a2a4407fa13c5cd7d0] root:267 - Proxied mode ip_address=127.0.0.1 port=8065 exposed_port=8000:
2017-06-06 13:40:05,001 DEBUG [5936a2a4407fa13c5cd7d0] custom:148 - LOAD: returning wrapper package: <virtual package: splunk.appserver.mrsparkle.custom_controllers.>
2017-06-06 13:40:05,002 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/instrumentation_controller.py
2017-06-06 13:40:05,002 DEBUG [5936a2a4407fa13c5cd7d0] custom:148 - LOAD: returning wrapper package: <virtual package: splunk.appserver.mrsparkle.custom_controllers.splunk_instrumentation>
2017-06-06 13:40:05,004 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/cherrypy.py
2017-06-06 13:40:05,004 DEBUG [5936a2a4407fa13c5cd7d0] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/traceback.py'
2017-06-06 13:40:05,004 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/traceback.py
2017-06-06 13:40:05,004 DEBUG [5936a2a4407fa13c5cd7d0] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/json.py'
2017-06-06 13:40:05,004 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/json.py
2017-06-06 13:40:05,004 DEBUG [5936a2a4407fa13c5cd7d0] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/logging.py'
2017-06-06 13:40:05,004 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/logging.py
2017-06-06 13:40:05,005 DEBUG [5936a2a4407fa13c5cd7d0] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/zipfile.py'
2017-06-06 13:40:05,005 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/zipfile.py
2017-06-06 13:40:05,005 DEBUG [5936a2a4407fa13c5cd7d0] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/StringIO.py'
2017-06-06 13:40:05,005 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/StringIO.py
2017-06-06 13:40:05,005 DEBUG [5936a2a4407fa13c5cd7d0] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/splunk.py'
2017-06-06 13:40:05,005 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/splunk.py
2017-06-06 13:40:05,005 DEBUG [5936a2a4407fa13c5cd7d0] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/datetime.py'
2017-06-06 13:40:05,005 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/datetime.py
2017-06-06 13:40:05,005 DEBUG [5936a2a4407fa13c5cd7d0] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/cherrypy.py'
2017-06-06 13:40:05,007 DEBUG [5936a2a4407fa13c5cd7d0] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/splunk_instrumentation.py'
2017-06-06 13:40:05,007 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/splunk_instrumentation.py
2017-06-06 13:40:05,007 DEBUG [5936a2a4407fa13c5cd7d0] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/string.py'
2017-06-06 13:40:05,007 DEBUG [5936a2a4407fa13c5cd7d0] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/splunk_instrumentation/appserver/controllers/string.py
2017-06-06 13:44:19,655 INFO [5936a2a4407fa13c5cd7d0] custom:211 - Registering custom app endpoint: splunk_instrumentation/instrumentation_controller

Moving the app folder to somewhere else and starting splunk results in an near instant startup:

2017-06-06 14:29:02,563 INFO    [5936ae1c147f2297de8790] root:267 - Proxied mode ip_address=127.0.0.1 port=8065 exposed_port=8000:
2017-06-06 14:29:02,904 DEBUG   [5936ae1c147f2297de8790] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/Splunk_TA_nix/appserver/controllers/json.py'
2017-06-06 14:29:02,904 DEBUG   [5936ae1c147f2297de8790] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/Splunk_TA_nix/appserver/controllers/json.py
2017-06-06 14:29:02,904 DEBUG   [5936ae1c147f2297de8790] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/Splunk_TA_nix/appserver/controllers/setup.py
2017-06-06 14:29:02,904 DEBUG   [5936ae1c147f2297de8790] custom:148 - LOAD: returning wrapper package: <virtual package: splunk.appserver.mrsparkle.custom_controllers.Splunk_TA_nix>
2017-06-06 14:29:02,904 DEBUG   [5936ae1c147f2297de8790] custom:148 - LOAD: returning wrapper package: <virtual package: splunk.appserver.mrsparkle.custom_controllers.>
2017-06-06 14:29:02,905 DEBUG   [5936ae1c147f2297de8790] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/Splunk_TA_nix/appserver/controllers/splunk.py'
2017-06-06 14:29:02,905 DEBUG   [5936ae1c147f2297de8790] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/Splunk_TA_nix/appserver/controllers/splunk.py
2017-06-06 14:29:02,905 DEBUG   [5936ae1c147f2297de8790] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/Splunk_TA_nix/appserver/controllers/cherrypy.py'
2017-06-06 14:29:02,905 DEBUG   [5936ae1c147f2297de8790] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/Splunk_TA_nix/appserver/controllers/cherrypy.py
2017-06-06 14:29:02,905 DEBUG   [5936ae1c147f2297de8790] custom:162 - [Errno 2] No such file or directory: '/opt/splunk/etc/apps/Splunk_TA_nix/appserver/controllers/sys.py'
2017-06-06 14:29:02,905 DEBUG   [5936ae1c147f2297de8790] custom:154 - LOAD: reading file: /opt/splunk/etc/apps/Splunk_TA_nix/appserver/controllers/sys.py
2017-06-06 14:29:02,906 DEBUG   [5936ae1c147f2297de8790] root:452 - No shared storage location configured, using: /opt/splunk/var/run/splunk/rss
2017-06-06 14:29:02,906 DEBUG   [5936ae1c147f2297de8790] root:446 - Checking for shared storage location
2017-06-06 14:29:02,906 INFO    [5936ae1c147f2297de8790] custom:211 - Registering custom app endpoint: Splunk_TA_nix/setup

I have managed to workaround the issue for now by creating /opt/splunk/etc/apps/splunk_instrumentation/local/app.conf with the following parameters:

[install]
allows_disable = true
state = disabled

Hopefully this helps anyone else with slow startup issues, and perhaps someone can shed some light as to why this app, which is supposed to do background telemetry, is causing such an impact.

Thanks,

Carl

[mshelley7]

I have upgraded my cluster and can confirm that this is fixed in 6.6.3

[mshelley7]

I have just upgrade my cluster and I can confirm that it has been fixed.

[michaell_splunk]

This bug was fixed in 6.6.3 (SPL-141718):

http://docs.splunk.com/Documentation/Splunk/6.6.3/ReleaseNotes/6.6.3

[echalex]

I was struggling with this too.
Based on thejohn's comment above, it's clear that splunkweb is slow to start when it can't reach the update URL, e.g. when behind a corporate firewall and not using a proxy.

The solution by thejohn works, but if you have a coroporate proxy, you can also get this working by setting the https_proxy environment variable. This will allow splunk to perform the normal update checks. Apparently you can't disable this in web.conf...

I reduced my startup time from 5 minutes (sic) to 5 seconds by putting this in my splunk user's .bash_profile:

export https_proxy=https://proxy.corporation.com:8080

On a server which doesn't have access to the proxy, I just put the following in my splunk-launch.conf:

QUICKDRAW_URL=0

[thejohn]

This is cause by https://quickdraw.splunk.com being unreachable. Another work around is to set environment variable QUICKDRAW_URL to anything.

[echalex]

Thanks, thejohn.

I suggest you change your comment to an answer.

[mshelley7]

Thanks Carl for this, I too have had problems with slow startup on Splunk when testing 6.6.1. I have created a case for Splunk to investigate or provide comment.

[carlalldis]

Great, I thought I was going mad. I also have a support case ongoing with Splunk who cannot reproduce the issue as of yet. I am doing some diagnostic traces for them to review. Hopefully we will find the cause of the bug as it seems to be environment related.

[mshelley7]

Just off interest, what Operating System are you using? I am using Ubuntu 16.04.2

[carlalldis]

Red Hat 7. I also get the issue on a personal Centos 7 instance. Both are fully up to date.