SplunkWeb fails to start - timeout when binding to port

[crazygir]

The problem:

When trying to start splunk, splunkweb errors out (supposedly on binding to the port, but I am skeptical given the notes below).

Here is me starting splunk:

splunk:/opt/splunk# ps aux |grep splunk
root      9847  0.0  0.0   5164   772 pts/2    S+   18:14   0:00 grep splunk
splunk:/opt/splunk# bin/splunk start

Splunk> All batbelt. No tights.

Checking prerequisites...
    Checking http port [8080]: open
    Checking mgmt port [8089]: open
    Checking configuration...  Done.
    Checking index directory...  Done.
    Checking databases...
    Validated databases: _audit, _blocksignature, _internal, _thefishbucket, history, main, sample, summary
All preliminary checks passed.

Starting splunk server daemon (splunkd)... Done.
Starting splunkweb...
Timed out waiting for splunkweb to start.
splunk:/opt/splunk#

splunk:/opt/splunk# ps aux | grep splunk
root      4106  0.0  0.0   5164   772 pts/2    S+   10:04   0:00 grep splunk
root      9913  0.2  6.2 179764 56428 ?        Sl   Oct12   2:01 splunkd -p 8089 start
root      9916  0.0  0.7  47076  7060 ?        Ss   Oct12   0:03 splunkd -p 8089 start

SplunkWeb Log Posted At End

Notes:

EDIT :: In the following code snippets/logs I have masked the server IP with a.b.c.d

Here are my (only) local changes, trying to get this working (and following suggestions from IRC / the old splunk forum):

splunk:/opt/splunk# cat etc/system/local/web.conf
[settings]
server.socket_host = a.b.c.d
httpport = 8080

About the system:

• default/stock install of Debian Lenny, AMD64
• no other services are running, except SSH
• nothing should be binding to these ports, except SPLUNK

What I have tried/Resolution:

• specified the system's IP explicitly, so that cherrypy is not trying to bind to 0.0.0.0 but a.b.c.d. Starting slunk reflected this change, though splunkweb was still unable to start up.

• specified the port to bind to explicitly, again via web.conf, and again with the same results as above (change noted but had no affect).

• I con confirm running this as root, though this is a high port so that should not matter

• clean splunk install (have not done a wipe of the OS, but this is a stock debian install)

• netstat -an:

    splunk:~# netstat -an
    Active Internet connections (servers and established)
    Proto Recv-Q Send-Q Local Address           Foreign Address         State
    tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN
    tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN
    tcp        0      0 0.0.0.0:8089            0.0.0.0:*               LISTEN
    tcp        0     52 a.b.c.d:22              a.b.c.d:55142      ESTABLISHED
    tcp6       0      0 :::22                   :::*                    LISTEN
    udp        0      0 0.0.0.0:68              0.0.0.0:*
    udp        0      0 0.0.0.0:68              0.0.0.0:*
    udp        0      0 0.0.0.0:111             0.0.0.0:*

What is really weird.. is that splunkweb appears to come up (sometimes is even noted in the initial startup sequence) but after some time (see the time delay in the log) cherrypy errors out..

EDIT :: 4pm :: Here is another fun one:

splunk:/opt/splunk# strace -tt -v -f -o strace_splunkweb.log bin/splunk splunkweb start
Splunk is not running, and it must be for this operation. To start splunk, run "splunk start".
splunk:/opt/splunk# ps aux |grep splunk
root     16559  0.0  0.0   5164   776 pts/2    R+   16:27   0:00 grep splunk
root     17717  0.2  6.7 184952 60176 ?        Sl   10:40   0:49 splunkd -p 8089 start
root     17718  0.0  0.7  47076  7060 ?        Ss   10:40   0:01 splunkd -p 8089 start

it is as if the two are not communicating..

An Strace Log can be found here: http://filebin.ca/ctcooj

SplunkWeb Log: var/log/splunk/web_service.log

    2010-10-13 10:40:40,809 INFO    [4cb5c4e8b81056c10] __init__:160 - Using default logging config file: /opt/splunk/etc/log.cfg
    2010-10-13 10:40:40,810 INFO    [4cb5c4e8b81056c10] __init__:176 - Setting logger=splunk level=INFO
    2010-10-13 10:40:40,810 INFO    [4cb5c4e8b81056c10] __init__:176 - Setting logger=splunk.appserver level=INFO
    2010-10-13 10:40:40,810 INFO    [4cb5c4e8b81056c10] __init__:176 - Setting logger=splunk.appserver.controllers level=INFO
    2010-10-13 10:40:40,810 INFO    [4cb5c4e8b81056c10] __init__:176 - Setting logger=splunk.appserver.lib level=WARN
    2010-10-13 10:40:41,263 INFO    [4cb5c4e8b81056c10] lists:59 - List controller loaded: SavedSearchesListGenerator
    2010-10-13 10:40:41,263 INFO    [4cb5c4e8b81056c10] lists:59 - List controller loaded: JobsListGenerator
    2010-10-13 10:40:41,263 INFO    [4cb5c4e8b81056c10] lists:65 - Setting lists/jobs
    2010-10-13 10:40:41,263 INFO    [4cb5c4e8b81056c10] lists:59 - List controller loaded: EntitiesListGenerator
    2010-10-13 10:40:41,264 INFO    [4cb5c4e8b81056c10] lists:65 - Setting lists/entities
    2010-10-13 10:40:41,264 INFO    [4cb5c4e8b81056c10] lists:59 - List controller loaded: SavedListGenerator
    2010-10-13 10:40:41,264 INFO    [4cb5c4e8b81056c10] lists:65 - Setting lists/saved
    2010-10-13 10:43:50,281 ERROR   [4cb5c4e8b81056c10] startup:45 - Unable to read in product version information; Splunkd daemon is not responding: ('[Errno 110] Connection timed out',)
    2010-10-13 10:43:50,282 INFO    [4cb5c4e8b81056c10] root:141 - ENGINE: Listening for SIGHUP.
    2010-10-13 10:43:50,282 INFO    [4cb5c4e8b81056c10] root:141 - ENGINE: Listening for SIGTERM.
    2010-10-13 10:43:50,282 INFO    [4cb5c4e8b81056c10] root:141 - ENGINE: Listening for SIGUSR1.
    2010-10-13 10:43:50,282 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: DISPATCH_TIME_FORMAT (str): %s.%Q
    2010-10-13 10:43:50,283 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: SSOMode (str): permissive
    2010-10-13 10:43:50,283 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: build_number (str): 000
    2010-10-13 10:43:50,283 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: caCertPath (str): /certs/cert.pem
    2010-10-13 10:43:50,283 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: compressStaticFiles (bool): True
    2010-10-13 10:43:50,283 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: docsCheckerBaseURL (str): http://quickdraw.splunk.com/help
    2010-10-13 10:43:50,283 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: enableSplunkWebSSL (bool): False
    2010-10-13 10:43:50,283 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: enable_autocomplete_login (bool): False
    2010-10-13 10:43:50,284 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: enable_gzip (bool): True
    2010-10-13 10:43:50,284 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: enable_insecure_login (bool): False
    2010-10-13 10:43:50,284 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: enable_proxy_write (bool): False
    2010-10-13 10:43:50,284 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: engine.autoreload_on (bool): False
    2010-10-13 10:43:50,284 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: error_page.default (function): 
    2010-10-13 10:43:50,285 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: etc_path (str): /opt/splunk/etc
    2010-10-13 10:43:50,285 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: flash_major_version (int): 9
    2010-10-13 10:43:50,285 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: flash_minor_version (int): 0
    2010-10-13 10:43:50,285 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: flash_revision_version (int): 124
    2010-10-13 10:43:50,285 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: httpport (int): 8080
    2010-10-13 10:43:50,285 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: is_free_license (bool): False
    2010-10-13 10:43:50,286 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: is_trial_license (bool): True
    2010-10-13 10:43:50,286 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: js_logger_mode (str): None
    2010-10-13 10:43:50,286 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: js_logger_mode_server_end_point (str): util/log/js
    2010-10-13 10:43:50,286 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: js_logger_mode_server_max_buffer (int): 100
    2010-10-13 10:43:50,286 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: js_logger_mode_server_poll_buffer (int): 1000
    2010-10-13 10:43:50,286 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: js_no_cache (bool): False
    2010-10-13 10:43:50,286 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: license_state (str): OK
    2010-10-13 10:43:50,287 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: log.access_maxfiles (int): 5
    2010-10-13 10:43:50,287 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: log.access_maxsize (int): 25000000
    2010-10-13 10:43:50,287 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: log.error_maxfiles (int): 5
    2010-10-13 10:43:50,287 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: log.error_maxsize (int): 250000000
    2010-10-13 10:43:50,287 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: log.screen (bool): True
    2010-10-13 10:43:50,288 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: login_content (str):
    2010-10-13 10:43:50,288 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: mako_cache_path (str): /opt/splunk/var/run/splunk/mako_
    cache
    2010-10-13 10:43:50,288 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: mgmtHostPort (str): 127.0.0.1:8089
    2010-10-13 10:43:50,288 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: module_dir (str): share/splunk/search_mrsparkle/modules
    2010-10-13 10:43:50,288 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: mrsparkle_path (str): /opt/splunk/share/search/mrsparkl
    e
    2010-10-13 10:43:50,288 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: privKeyPath (str): /certs/privkey.pem
    2010-10-13 10:43:50,289 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: remoteUser (str): REMOTE_USER
    2010-10-13 10:43:50,289 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: request.show_tracebacks (bool): True
    2010-10-13 10:43:50,289 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: response.timeout (int): 7200
    2010-10-13 10:43:50,289 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: root_endpoint (str): /
    2010-10-13 10:43:50,289 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: rss_endpoint (str): /rss
    2010-10-13 10:43:50,289 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: server.max_request_body_size (int): 524288000
    2010-10-13 10:43:50,290 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: server.socket_host (str): a.b.c.d
    2010-10-13 10:43:50,290 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: server.socket_port (int): 8080
    2010-10-13 10:43:50,290 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: serviceFormPostURL (str): http://headlamp.splunk.com/ev
    ent/add
    2010-10-13 10:43:50,290 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: site_packages_path (str): /opt/splunk/lib/python2.6/sit
    e-packages
    2010-10-13 10:43:50,290 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: splunkdTrustedIP (NoneType): None
    2010-10-13 10:43:50,290 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: start_time (float): 1286981030.28
    2010-10-13 10:43:50,291 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: startwebserver (int): 1
    2010-10-13 10:43:50,291 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: static_dir (str): share/splunk/search_mrsparkle/exposed
    2010-10-13 10:43:50,291 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: static_endpoint (str): /static
    2010-10-13 10:43:50,291 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: staticdir (str): /opt/splunk/share/splunk/search_mrspar
    kle/exposed
    2010-10-13 10:43:50,291 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: supportSSLV3Only (bool): False
    2010-10-13 10:43:50,291 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: template_dir (str): share/splunk/search_mrsparkle/templ
    ates
    2010-10-13 10:43:50,292 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: testing_dir (str): share/splunk/testing
    2010-10-13 10:43:50,292 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: testing_endpoint (str): /testing
    2010-10-13 10:43:50,292 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.decode.on (bool): True
    2010-10-13 10:43:50,292 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.encode.encoding (str): utf-8
    2010-10-13 10:43:50,292 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.encode.on (bool): True
    2010-10-13 10:43:50,292 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.log_headers.on (bool): True
    2010-10-13 10:43:50,293 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.log_tracebacks.on (bool): True
    2010-10-13 10:43:50,293 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.sessions.name (str): session_id_8080
    2010-10-13 10:43:50,293 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.sessions.on (bool): True
    2010-10-13 10:43:50,293 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.sessions.storage_path (str): /opt/splunk/var/run/splunk
    2010-10-13 10:43:50,293 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.sessions.storage_type (str): file
    2010-10-13 10:43:50,293 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.sessions.timeout (int): 60
    2010-10-13 10:43:50,294 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: tools.trailing_slash.on (bool): True
    2010-10-13 10:43:50,294 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: ui_inactivity_timeout (int): 60
    2010-10-13 10:43:50,294 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: updateCheckerBaseURL (str): http://quickdraw.splunk.com/js/
    2010-10-13 10:43:50,294 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: use_future_expires (bool): True
    2010-10-13 10:43:50,294 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: userEntTrialRegistrationURL (str): https://www.splunk.com/index.php/sign_up?destination=prod_reg
    2010-10-13 10:43:50,294 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: userRegistrationURL (str): https://www.splunk.com/index.php/pre_reg?destination=prod_reg
    2010-10-13 10:43:50,295 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: userResendRegistrationURL (str): https://www.splunk.com/index.php/pre_reg?destination=prod_resend
    2010-10-13 10:43:50,295 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: version_label (str): UNKNOWN_VERSION
    2010-10-13 10:43:50,295 INFO    [4cb5c4e8b81056c10] root:428 - CONFIG: version_number (str): 4.0
    2010-10-13 10:43:50,295 INFO    [4cb5c4e8b81056c10] root:141 - ENGINE: Bus STARTING
    2010-10-13 10:43:50,295 WARNING [4cb5c4e8b81056c10] custompidfile:20 - Writing pidfile at /opt/splunk/var/run/splunk/splunkweb.pid (PID: 17819)"
    2010-10-13 10:43:50,308 INFO    [4cb5c4e8b81056c10] root:141 - ENGINE: Started monitor thread '_TimeoutMonitor'.
    2010-10-13 10:44:33,287 INFO    [4cb5c5d14819f4ad0] root:141 - ENGINE: Started monitor thread 'Monitor'.
    2010-10-13 10:44:45,721 ERROR   [4cb5c4e8b81056c10] root:141 - ENGINE: Error in 'start' listener >
    Traceback (most recent call last):
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/process/wspbus.py", line 147, in publish
        output.append(listener(*args, **kwargs))
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/_cpserver.py", line 91, in start
        ServerAdapter.start(self)
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/process/servers.py", line 60, in start
        self.wait()
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/process/servers.py", line 101, in wait
        wait_for_occupied_port(host, port)
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/process/servers.py", line 266, in wait_for_occupied_port
        raise IOError("Port %r not bound on %r" % (port, host))
    IOError: Port 8080 not bound on 'a.b.c.d'

    2010-10-13 10:44:45,722 ERROR   [4cb5c4e8b81056c10] root:141 - ENGINE: Shutting down due to error in start listener:
    Traceback (most recent call last):
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/process/wspbus.py", line 184, in start
        self.publish('start')
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/process/wspbus.py", line 147, in publish
        output.append(listener(*args, **kwargs))
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/_cpserver.py", line 91, in start
        ServerAdapter.start(self)
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/process/servers.py", line 60, in start
        self.wait()
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/process/servers.py", line 101, in wait
        wait_for_occupied_port(host, port)
      File "/opt/splunk/lib/python2.6/site-packages/cherrypy/process/servers.py", line 266, in wait_for_occupied_port
        raise IOError("Port %r not bound on %r" % (port, host))
    IOError: Port 8080 not bound on 'a.b.c.d'
    (END)

[ephemeric]

I know this sounds bad: disable all unneeded services except Splunk and reboot.

[Paolo_Prigione]

Might it be a hanging process already bound to port 8080?

Splunkweb binds to its web port through python: you won't find a "splunkweb" process. Here's an example (I run splunk as root, bound on port 8000):

#1) I get the process bound to port 8000
[root@fedosplunk ~]# lsof -i tcp:8000
COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF NODE NAME
python  3470 root    5u  IPv4  10336      0t0  TCP *:irdmi (LISTEN)

#2) I retrieve details about the process
[root@fedosplunk ~]# top -cp 3470
PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
3470 root      20   0  183m  28m 4832 S  0.0  4.0   0:38.71 python -O /opt/splunk/lib/python2.6/site-packages/splunk/appserver/mrsparkle/root.py restart

If that's the case, killing the hanging python process might solve the issue.

Paolo

[crazygir]

Hi Amrit,

About the system: default/stock install of Debian Lenny, AMD64; no other services are running, except SSH; nothing should be binding to these ports, except SPLUNK.

so, no, no selinux to make this more difficult (doens't RH always tell you to disable it anyway 😛 )

[crazygir]

crap, no formatting.. sorry!

[crazygir]

Hi JradkowskiAAMC,

thanks for the interest 🙂

Interesting that you have not been able to reproduce.. are you running Debian AMD64?

In answer to your questions:
- I am running the 64-bit version of Splunk: splunk-4.1.5-85165-linux-2.6-amd64.deb

• The system has two interfaces, one is active, one is not.. splunk is configured to use the active one and the correct IP.

• this is not a vm

• I have not tried setting up apache, but honestly, I don't see how that would help, given that splunk runs cherrypy, and other services are binding to ports just fine (even splunkd).

Thanks!

[amrit]

also, are you running selinux/grsec/anything like that?

[jradkowskiAAMC]

Are you running the 32bit version of Splunk? 64bit? What about other network interfaces? What is your /sbin/ifconfig output? Is this a VM or physical hardware? Lastly, are you able to install and run say Apache without issue?

I ask because I've tried this several times locally and I can't replicate it... and I like a good problem so you have my attention 🙂

[Johnvey]

Instead of binding on a hex IP address, try binding to '10.11.12.13' instead. Python doesn't seem to support binding on hex-as-string host values (tested on linux, OSX).

[crazygir]

I apologize for the confusion here: a.b.c.d in the above logs/etc were my masking the server IP. I am using an IPv4 IP address.