Friday, 14 November 2014

Hmmmm, HTTP404 and SRVE0190E seen with IBM HTTP Server and WebSphere Application Server

Hmm, so I am seeing this: -

Error 404: java.io.FileNotFoundException: SRVE0190E: File not found: /index.html

when I attempt to access a HTML page from IBM HTTP Server via HTTPS: -


even though I can get the page via HTTP: -


This is part of an IBM BPM Advanced 8.5.5 infrastructure, and the most recent change was to add IHS into the mix, federate it into the WAS cell, and add a Virtual Host entry for port 8443: -

cellID=AdminControl.getCell() 
AdminConfig.create('HostAlias', AdminConfig.getid('/Cell:'+cellID+'/VirtualHost:default_host/'), '[[hostname "*"] [port "8443"]]') 
AdminConfig.save() 
AdminNodeManagement.syncActiveNodes() 
quit 


I tried enabling further debugging in IHS by changing: -

LogLevel warn

to: -

LogLevel debug

in: -

/opt/IBM/HTTPServer/conf/httpd.conf

but the only thing that popped up in access_log was: -

192.168.1.70 - - [14/Nov/2014:15:08:26 +0000] "GET / HTTP/1.1" 404 42

and nothing useful in error_log.

I wondered whether the problem was related to the WAS Plugin, which was configured at the end of httpd.conf : -

LoadModule was_ap22_module "/opt/IBM/WebSphere/Plugins/bin/64bits/mod_was_ap22_http.so"
WebSpherePluginConfig /opt/IBM/WebSphere/Plugins/config/webserver1/plugin-cfg.xml

so I temporarily commented out both lines, and restarted IHS.

At that point, getting index.html via HTTP *and* HTTPS worked a treat.

So it's definitely somehow related to the Plugin and/or WAS.

I enabled debug in the plugin, by changing: -

   <Log LogLevel="Error" Name="/opt/IBM/WebSphere/Plugins/logs/webserver1/http_plugin.log"/>

to: -

   <Log LogLevel="Debug" Name="/opt/IBM/WebSphere/Plugins/logs/webserver1/http_plugin.log"/>

in: -

/opt/IBM/WebSphere/Plugins/config/webserver1/plugin-cfg.xml 

and can see: -

[14/Nov/2014:15:01:23.89900] 000045c2 057fb700 - DETAIL:    GET /index.html HTTP/1.1
[14/Nov/2014:15:01:23.89901] 000045c2 057fb700 - DETAIL:    Host: bpm855.uk.ibm.com:8443
[14/Nov/2014:15:01:23.89901] 000045c2 057fb700 - DETAIL:    Cache-Control: max-age=0
[14/Nov/2014:15:01:23.89902] 000045c2 057fb700 - DETAIL:    Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
[14/Nov/2014:15:01:23.89902] 000045c2 057fb700 - DETAIL:    User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_10_0) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.122 Safari/537.36
[14/Nov/2014:15:01:23.89903] 000045c2 057fb700 - DETAIL:    DNT: 1
[14/Nov/2014:15:01:23.89903] 000045c2 057fb700 - DETAIL:    Accept-Encoding: gzip,deflate,sdch
[14/Nov/2014:15:01:23.89904] 000045c2 057fb700 - DETAIL:    Accept-Language: en-US,en;q=0.8
[14/Nov/2014:15:01:23.89905] 000045c2 057fb700 - DETAIL:    Cookie: JSESSIONID=00002GxGEWjz6XsUDTV69LDQYmi:196509vjn; CoreID6=40736703432114159613577&ci=50200000|ESTKCS; UnicaNIODID=JOlYGvtFslm-Y5kRjJ7; CoreM_State=72~-1~-1~-1~-1~3~3~5~3~3~7~7~|~~|~~|~~|~||||||~|~~|~~|~~|~~|~~|~~|~~|~; CoreM_State_Content=6~|~38D1983DAF0161AD~|~0; 50200000|ESTKCS_clogin=v=1&l=1415961357&e=1415963160646; LtpaToken2=ELcJ3s000hNQAmekT9IFK4NhSC419BFnN4WsQxjSBdXOIt78jL/UVc/tSQd4p+wBCpygJwkLG51qhZQcYOoZN0PNsYOwLyow8ERnvf4jeWyqw45ZetsBSErQjemaZHoHXMyO8c85FdH4edxT5M5AFdojKPpKKAabTKe94Jm2KAlsGb6Mw5BkQMkVIIocUMqTFqpoyBxmxGbADGAjJ86eiI+1MtYQXVFYggAIevtQllckeB77xEkionOnm1q0POYq+5CLdjVpGxXE0sizd2vua5iySBjWoIuIR6pfhfBw8DE8htetEXvHzJlDBErGXcUdo43zMeQQINzSxAYzWsEvlxjxCqYEuEpYSzplj7Kf8RmM4QSjtYWc+v9ZmHYgGBA9; sessionCode=514564614; TJE=; TE3=
[14/Nov/2014:15:01:23.89905] 000045c2 057fb700 - DETAIL:    $WSCS: TLS_RSA_WITH_AES_128_GCM_SHA256
[14/Nov/2014:15:01:23.89906] 000045c2 057fb700 - DETAIL:    $WSIS: true
[14/Nov/2014:15:01:23.89907] 000045c2 057fb700 - DETAIL:    $WSSC: https
[14/Nov/2014:15:01:23.89907] 000045c2 057fb700 - DETAIL:    $WSPR: HTTP/1.1
[14/Nov/2014:15:01:23.89908] 000045c2 057fb700 - DETAIL:    $WSRA: 192.168.1.70
[14/Nov/2014:15:01:23.89908] 000045c2 057fb700 - DETAIL:    $WSRH: 192.168.1.70
[14/Nov/2014:15:01:23.89909] 000045c2 057fb700 - DETAIL:    $WSSN: bpm855.uk.ibm.com
[14/Nov/2014:15:01:23.89909] 000045c2 057fb700 - DETAIL:    $WSSP: 8443
[14/Nov/2014:15:01:23.89910] 000045c2 057fb700 - DETAIL:    $WSSI: wkUAAOMXLq4ktsQ6fdbYIboGeENYWFhYQxlmVAAAAAI=
[14/Nov/2014:15:01:23.89910] 000045c2 057fb700 - DETAIL:    Surrogate-Capability: WS-ESI="ESI/1.0+"
[14/Nov/2014:15:01:23.89911] 000045c2 057fb700 - DETAIL:    _WS_HAPRT_WLMVERSION: -1
[14/Nov/2014:15:01:23.89916] 000045c2 057fb700 - DEBUG: ws_common: websphereExecute: Wrote the request; reading the response (timeout 900)
[14/Nov/2014:15:01:23.89917] 000045c2 057fb700 - DETAIL: lib_htresponse: htresponseRead: Reading the response: f002ab30
[14/Nov/2014:15:01:23.90631] 000045c2 057fb700 - DETAIL:    HTTP/1.1 404 Not Found
[14/Nov/2014:15:01:23.90637] 000045c2 057fb700 - DETAIL:    X-Powered-By: Servlet/3.0
[14/Nov/2014:15:01:23.90638] 000045c2 057fb700 - DETAIL:    Content-Type: text/html;charset=ISO-8859-1
[14/Nov/2014:15:01:23.90639] 000045c2 057fb700 - DETAIL:    $WSEP:
[14/Nov/2014:15:01:23.90639] 000045c2 057fb700 - DETAIL:    Content-Language: en-GB


in: -

/opt/IBM/WebSphere/Plugins/logs/webserver1/http_plugin.log

So this suggests that the request is being forwarded, by IHS, via the WAS Plugin, to WAS.

So I drilled into the plugin-cfg.xml file a bit more.

Logic dictated that the problem was somehow related to the context root of the URL, in that the page I'm requesting - /index.html - doesn't have the usual context root of, say, /ProcessCenter or /ProcessPortal.

Lo and behold, in plugin-cfg.xml, I can see: -

   <ServerCluster CloneSeparatorChange="false" GetDWLMTable="false" IgnoreAffinityRequests="false" LoadBalance="Round Robin" Name="dmgr_Dmgr_Cluster" PostBufferSize="0" PostSizeLimit="-1" RemoveSpecialHeaders="true" RetryInterval="60" ServerIOTimeoutRetry="-1">
      <Server ConnectTimeout="0" ExtendedHandshake="false" MaxConnections="-1" Name="Dmgr_dmgr" ServerIOTimeout="900" WaitForContinue="false"/>
   </ServerCluster>
   <UriGroup Name="default_host_AppCluster_URIs">
...
<Uri AffinityCookie="JSESSIONID" AffinityURLIdentifier="jsessionid" Name="/*"/>
...
   </UriGroup>
   <Route ServerCluster="AppCluster" UriGroup="default_host_AppCluster_URIs" VirtualHostGroup="default_host"/>

Now where did that little sucker come from ?

I checked the source, which is held at the WAS cell level: -

/opt/IBM/WebSphere/AppServer/profiles/Dmgr01/config/cells/PCCell1/nodes/Node1/servers/webserver1

which has the same thing.

I'm going to retrace my steps but .... at least I have a successful resolution / circumvention, which is nice.

2 comments:

Chris Willhoite said...

Have you found a permanent solution to this? I'm having a similar issue with WebSphere 8.5 and Maximo 7.6. I have a PMR in with IBM, but they have been slow to respond.

Dave Hay said...

Hi Chris, nope, I've not seen the problem since. It looks like I had an application in WAS that, when I mapped it to the federated-in IHS, added the URI pattern for the context root of / rather than, say, /mum or /rest or /snoop.

Once I worked out the symptom i.e. the malformed URI in the plugin configuration, and removed it, it was all good :-)