[GLASSFISH-20694] Glassfish 4.0 and jk Unable to populate SSL attributes Created: 10/Jul/13  Updated: 19/Sep/14  Resolved: 17/Jul/13

Status: Resolved
Project: glassfish
Component/s: web_container
Affects Version/s: 4.0
Fix Version/s: 4.1

Type: Bug Priority: Major
Reporter: buddypine Assignee: oleksiys
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Glassfish 4.0 b89, Apache 2.2.22 mod_proxy_ajp


Tags: ajp, apache, proxy

 Description   

I am using a jk enabled listener behind Apache.

GF listener created as follows:
% asadmin create-network-listener --jkenabled true --protocol http-listener-1 --listenerport 8009 jk-listener

Apache httpd-ssl.conf mod_proxy_ajp
------------------------------------------
ProxyPass / ajp://localhost:8009/
ProxyPassReverse / ajp://localhost:8009/

All seems to work fine and I can connect using SSL to Apache which proxies the requests through to Glassfish but I get the exception below in the logs (this does not happen with GF 3):

[2013-07-10T15:06:37.929+0200] [glassfish 4.0] [WARNING] [] [org.glassfish.grizzly.http.server.util.RequestUtils] [tid: _ThreadID=53 _ThreadName=jk-listener(4)] [timeMillis: 1373461597929] [levelValue: 900] [[
Unable to populate SSL attributes
java.lang.IllegalStateException: SSLEngine is null
at org.glassfish.grizzly.ssl.SSLSupportImpl.<init>(SSLSupportImpl.java:87)
at org.glassfish.grizzly.http.server.util.RequestUtils.populateSSLAttributes(RequestUtils.java:85)
at org.glassfish.grizzly.http.server.Request.getAttribute(Request.java:865)
at org.apache.catalina.connector.Request.populateSSLAttributes(Request.java:4581)
at org.apache.catalina.connector.Request.getAttributeNames(Request.java:1412)
at org.apache.catalina.connector.RequestFacade.getAttributeNames(RequestFacade.java:367)
at org.jboss.weld.context.beanstore.http.RequestBeanStore.getAttributeNames(RequestBeanStore.java:48)
at org.jboss.weld.context.beanstore.AttributeBeanStore.getPrefixedAttributeNames(AttributeBeanStore.java:207)
at org.jboss.weld.context.beanstore.AttributeBeanStore.attach(AttributeBeanStore.java:106)
at org.jboss.weld.context.http.HttpRequestContextImpl.associate(HttpRequestContextImpl.java:52)
at org.jboss.weld.context.http.HttpRequestContextImpl.associate(HttpRequestContextImpl.java:37)
at org.jboss.weld.servlet.WeldListener.requestInitialized(WeldListener.java:190)
at org.apache.catalina.core.StandardContext.fireRequestInitializedEvent(StandardContext.java:5225)
at org.apache.catalina.core.StandardHostValve.preInvoke(StandardHostValve.java:647)
at org.apache.catalina.core.StandardHostValve.__invoke(StandardHostValve.java:166)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java)
at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:357)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:260)
at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:188)
at org.glassfish.grizzly.http.server.HttpHandler.runService(HttpHandler.java:191)
at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:168)
at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:189)
at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:288)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:206)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:136)
at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:114)
at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:838)
at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:113)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:564)
at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:544)
at java.lang.Thread.run(Thread.java:724)
]]



 Comments   
Comment by Shing Wai Chan [ 10/Jul/13 ]

The exception is from org.glassfish.grizzly.ssl.SSLSupportImpl in Grizzly. Assign to Alexey for further investigation.

Comment by oleksiys [ 12/Jul/13 ]

looks like apache doesn't pass all the SSL information to Glassfish.
Can you pls. share the entire ssl.conf?

Comment by buddypine [ 12/Jul/13 ]

Sure:

 
#
# This is the Apache server configuration file providing SSL support.
# It contains the configuration directives to instruct the server how to
# serve pages over an https connection. For detailing information about these 
# directives see <URL:http://httpd.apache.org/docs/2.2/mod/mod_ssl.html>
# 
# Do NOT simply read the instructions in here without understanding
# what they do.  They're here only as hints or reminders.  If you are unsure
# consult the online docs. You have been warned.  
#

#
# Pseudo Random Number Generator (PRNG):
# Configure one or more sources to seed the PRNG of the SSL library.
# The seed data should be of good random quality.
# WARNING! On some platforms /dev/random blocks if not enough entropy
# is available. This means you then cannot use the /dev/random device
# because it would lead to very long connection times (as long as
# it requires to make more entropy available). But usually those
# platforms additionally provide a /dev/urandom device which doesn't
# block. So, if available, use this one instead. Read the mod_ssl User
# Manual for more details.
#
#SSLRandomSeed startup file:/dev/random  512
#SSLRandomSeed startup file:/dev/urandom 512
#SSLRandomSeed connect file:/dev/random  512
#SSLRandomSeed connect file:/dev/urandom 512


#
# When we also provide SSL we have to listen to the 
# standard HTTP port (see above) and to the HTTPS port
#
# Note: Configurations that use IPv6 but not IPv4-mapped addresses need two
#       Listen directives: "Listen [::]:443" and "Listen 0.0.0.0:443"
#
Listen 443

##
##  SSL Global Context
##
##  All SSL configuration in this context applies both to
##  the main server and all SSL-enabled virtual hosts.
##

#
#   Some MIME-types for downloading Certificates and CRLs
#
AddType application/x-x509-ca-cert .crt
AddType application/x-pkcs7-crl    .crl

#   Pass Phrase Dialog:
#   Configure the pass phrase gathering process.
#   The filtering dialog program (`builtin' is a internal
#   terminal dialog) has to provide the pass phrase on stdout.
SSLPassPhraseDialog  builtin

#   Inter-Process Session Cache:
#   Configure the SSL Session Cache: First the mechanism 
#   to use and second the expiring timeout (in seconds).
#SSLSessionCache         "dbm:/private/var/run/ssl_scache"
SSLSessionCache        "shmcb:/private/var/run/ssl_scache(512000)"
SSLSessionCacheTimeout  300

#   Semaphore:
#   Configure the path to the mutual exclusion semaphore the
#   SSL engine uses internally for inter-process synchronization. 
SSLMutex  "file:/private/var/run/ssl_mutex"

##
## SSL Virtual Host Context
##

<VirtualHost _default_:443>

#   General setup for the virtual host
DocumentRoot "/Library/WebServer/Documents"

ServerAdmin you@example.com
ErrorLog "/private/var/log/apache2/error_log"
TransferLog "/private/var/log/apache2/access_log"

ServerName myapp.local.inversebit.com:443
ProxyPass / ajp://myapp.local.inversebit.com:8009/
ProxyPassReverse / ajp://myapp.local.inversebit.com:8009/

#   SSL Engine Switch:
#   Enable/Disable SSL for this virtual host.
SSLEngine on

#   SSL Cipher Suite:
#   List the ciphers that the client is permitted to negotiate.
#   See the mod_ssl documentation for a complete list.
SSLCipherSuite ALL:!ADH:!EXPORT56:RC4+RSA:+HIGH:+MEDIUM:+LOW:+SSLv2:+EXP:+eNULL

#   Server Certificate:
#   Point SSLCertificateFile at a PEM encoded certificate.  If
#   the certificate is encrypted, then you will be prompted for a
#   pass phrase.  Note that a kill -HUP will prompt again.  Keep
#   in mind that if you have both an RSA and a DSA certificate you
#   can configure both in parallel (to also allow the use of DSA
#   ciphers, etc.)
#SSLCertificateFile "/private/etc/apache2/server.crt"
#SSLCertificateFile "/private/etc/apache2/server-dsa.crt"

SSLCertificateFile /Users/phill/etc/certs/newcert.pem
SSLCertificateKeyFile /Users/phill/etc/certs/webserver.nopass.key
SSLCACertificateFile /Users/phill/etc/certs/demoCA/cacert.pem
SSLCARevocationPath /Users/phill/etc/certs/demoCA/crl

#   Server Private Key:
#   If the key is not combined with the certificate, use this
#   directive to point at the key file.  Keep in mind that if
#   you've both a RSA and a DSA private key you can configure
#   both in parallel (to also allow the use of DSA ciphers, etc.)
#SSLCertificateKeyFile "/private/etc/apache2/server.key"
#SSLCertificateKeyFile "/private/etc/apache2/server-dsa.key"

#   Server Certificate Chain:
#   Point SSLCertificateChainFile at a file containing the
#   concatenation of PEM encoded CA certificates which form the
#   certificate chain for the server certificate. Alternatively
#   the referenced file can be the same as SSLCertificateFile
#   when the CA certificates are directly appended to the server
#   certificate for convinience.
#SSLCertificateChainFile "/private/etc/apache2/server-ca.crt"

#   Certificate Authority (CA):
#   Set the CA certificate verification path where to find CA
#   certificates for client authentication or alternatively one
#   huge file containing all of them (file must be PEM encoded)
#   Note: Inside SSLCACertificatePath you need hash symlinks
#         to point to the certificate files. Use the provided
#         Makefile to update the hash symlinks after changes.
#SSLCACertificatePath "/private/etc/apache2/ssl.crt"
#SSLCACertificateFile "/private/etc/apache2/ssl.crt/ca-bundle.crt"

#   Certificate Revocation Lists (CRL):
#   Set the CA revocation path where to find CA CRLs for client
#   authentication or alternatively one huge file containing all
#   of them (file must be PEM encoded)
#   Note: Inside SSLCARevocationPath you need hash symlinks
#         to point to the certificate files. Use the provided
#         Makefile to update the hash symlinks after changes.
#SSLCARevocationPath "/private/etc/apache2/ssl.crl"
#SSLCARevocationFile "/private/etc/apache2/ssl.crl/ca-bundle.crl"

#   Client Authentication (Type):
#   Client certificate verification type and depth.  Types are
#   none, optional, require and optional_no_ca.  Depth is a
#   number which specifies how deeply to verify the certificate
#   issuer chain before deciding the certificate is not valid.
#SSLVerifyClient require
#SSLVerifyDepth  10

#   Access Control:
#   With SSLRequire you can do per-directory access control based
#   on arbitrary complex boolean expressions containing server
#   variable checks and other lookup directives.  The syntax is a
#   mixture between C and Perl.  See the mod_ssl documentation
#   for more details.
#<Location />
#SSLRequire (    %{SSL_CIPHER} !~ m/^(EXP|NULL)/ \
#            and %{SSL_CLIENT_S_DN_O} eq "Snake Oil, Ltd." \
#            and %{SSL_CLIENT_S_DN_OU} in {"Staff", "CA", "Dev"} \
#            and %{TIME_WDAY} >= 1 and %{TIME_WDAY} <= 5 \
#            and %{TIME_HOUR} >= 8 and %{TIME_HOUR} <= 20       ) \
#           or %{REMOTE_ADDR} =~ m/^192\.76\.162\.[0-9]+$/
#</Location>

#   SSL Engine Options:
#   Set various options for the SSL engine.
#   o FakeBasicAuth:
#     Translate the client X.509 into a Basic Authorisation.  This means that
#     the standard Auth/DBMAuth methods can be used for access control.  The
#     user name is the `one line' version of the client's X.509 certificate.
#     Note that no password is obtained from the user. Every entry in the user
#     file needs this password: `xxj31ZMTZzkVA'.
#   o ExportCertData:
#     This exports two additional environment variables: SSL_CLIENT_CERT and
#     SSL_SERVER_CERT. These contain the PEM-encoded certificates of the
#     server (always existing) and the client (only existing when client
#     authentication is used). This can be used to import the certificates
#     into CGI scripts.
#   o StdEnvVars:
#     This exports the standard SSL/TLS related `SSL_*' environment variables.
#     Per default this exportation is switched off for performance reasons,
#     because the extraction step is an expensive operation and is usually
#     useless for serving static content. So one usually enables the
#     exportation for CGI and SSI requests only.
#   o StrictRequire:
#     This denies access when "SSLRequireSSL" or "SSLRequire" applied even
#     under a "Satisfy any" situation, i.e. when it applies access is denied
#     and no other module can change it.
#   o OptRenegotiate:
#     This enables optimized SSL connection renegotiation handling when SSL
#     directives are used in per-directory context. 
#SSLOptions +FakeBasicAuth +ExportCertData +StrictRequire
<FilesMatch "\.(cgi|shtml|phtml|php)$">
    SSLOptions +StdEnvVars
</FilesMatch>
<Directory "/Library/WebServer/CGI-Executables">
    SSLOptions +StdEnvVars
</Directory>

#   SSL Protocol Adjustments:
#   The safe and default but still SSL/TLS standard compliant shutdown
#   approach is that mod_ssl sends the close notify alert but doesn't wait for
#   the close notify alert from client. When you need a different shutdown
#   approach you can use one of the following variables:
#   o ssl-unclean-shutdown:
#     This forces an unclean shutdown when the connection is closed, i.e. no
#     SSL close notify alert is send or allowed to received.  This violates
#     the SSL/TLS standard but is needed for some brain-dead browsers. Use
#     this when you receive I/O errors because of the standard approach where
#     mod_ssl sends the close notify alert.
#   o ssl-accurate-shutdown:
#     This forces an accurate shutdown when the connection is closed, i.e. a
#     SSL close notify alert is send and mod_ssl waits for the close notify
#     alert of the client. This is 100% SSL/TLS standard compliant, but in
#     practice often causes hanging connections with brain-dead browsers. Use
#     this only for browsers where you know that their SSL implementation
#     works correctly. 
#   Notice: Most problems of broken clients are also related to the HTTP
#   keep-alive facility, so you usually additionally want to disable
#   keep-alive for those clients, too. Use variable "nokeepalive" for this.
#   Similarly, one has to force some clients to use HTTP/1.0 to workaround
#   their broken HTTP/1.1 implementation. Use variables "downgrade-1.0" and
#   "force-response-1.0" for this.
BrowserMatch ".*MSIE.*" \
         nokeepalive ssl-unclean-shutdown \
         downgrade-1.0 force-response-1.0

#   Per-Server Logging:
#   The home of a custom SSL log file. Use this when you want a
#   compact non-error SSL logfile on a virtual host basis.
CustomLog "/private/var/log/apache2/ssl_request_log" \
          "%t %h %{SSL_PROTOCOL}x %{SSL_CIPHER}x \"%r\" %b"

</VirtualHost>                                  
Comment by oleksiys [ 16/Jul/13 ]

Ok, looks like jboss.weld tries to retrieve client certificate, which is not available because Apache didn't forward it to us.
The exception itself doesn't have any impact on execution flow, except flooding server.log w/ the stacktrace.

We have reduced the logging level of the exception to FINE, so it will not occur in the server.log in normal case.
As a workaround you can change the logging level (via admin gui) of "org.glassfish.grizzly.http.server.util.RequestUtils" to "SEVERE"

Comment by oleksiys [ 17/Jul/13 ]

marking as fixed and closing the issue.
feel free to reopen it if needed.

thanks.

Comment by juliohm [ 04/Aug/13 ]

Greetings,

I am attempting to pass on the SSL authentication from Apache into Glassfish using mod_jk. I found the same exception reported here, and a call to

request.getAttribute("javax.servlet.request.X509Certificate");

returns null.

Other have also reported:

The exception itself doesn't have any impact on execution flow, except flooding server.log w/ the stacktrace.

Could this exception be the cause of it? Or am I doing something wrong with mod_jk at this point?

Comment by oleksiys [ 06/Aug/13 ]

@juliohm
most probably your client (may be browser) doesn't sent its certificate.
You may want to force clients to send their certificates by adding/uncommenting this in the Apache ssl.conf:

SSLVerifyClient require
Comment by juliohm [ 06/Aug/13 ]

Oddly, I already have the SSL config in the VirtualHost.

I can connect fine using a web browser and the appropriate certificates.

I've been trying to understand how the mod_jk module works, but I can't get a grip on the concept. Since it's forwarding the SSL authentication to a backend glassfish, does the java server need to receive this through its SSL listener as well (standard port 8181)? Or are the SSL credentials simply filled within the clear HTTP listener (8080)?.

Do I even need the same certificates in Java keystore as well as in Apache?

Comment by oleksiys [ 06/Aug/13 ]

Client certificate should be forwarded to Glassfish as part of Jk request, so you don't need any additional listeners neither https nor http.
But in your case you said

request.getAttribute("javax.servlet.request.X509Certificate");

return null, which IMO means Apache/mod_jk doesn't forward the certificate. Did you try to set SSLVerfyClient flag to "require"?

Comment by juliohm [ 06/Aug/13 ]

This is the basic setup I have in my VirtualHost (comments and related file paths redacted)

<VirtualHost ...>
   ......
   JkMount /gf_forward/* ajp13_worker
   SSLEngine on
   SSLProtocol all -SSLv2
   SSLHonorCipherOrder On
   SSLCipherSuite .......
   SSLCertificateFile    /path/to/certfile
   SSLCertificateKeyFile /path/to/keyfile
   SSLCACertificateFile /path/to/ca/certfile
   SSLCARevocationFile /path/to/crlfile
   SSLVerifyClient require
   SSLVerifyDepth  10
   ......
</VirtualHost>

I just find it funny that connections are correctly directed to glassfish. I can navigate whatever service is deployed in there. For example https://myserver/gf_forward/myapp works just fine. But I can see from my server.log that the request attribute "javax.servlet.request.X509Certificate" resolves to null.

I'm actually not sure what's going on

Comment by oleksiys [ 07/Aug/13 ]

Do you have this set?

JkOptions +ForwardSSLCertChain 

If it still doesn't work, can you pls. share your apache configuration (pls. send to oleksiys [at] java.net).

Comment by juliohm [ 07/Aug/13 ]

I was finally able to get it working! After several days, one of my friends had this insight.

SSLOptions +StdEnvVars +ExportCertData

You need ExportCertData enabled in SSLOptions. Now the certificate shows up in the request inside glassfish.

This is not much related to the ticket here, so I'm glad to this out of the way from this therad. Thank you very much for the help.





[GLASSFISH-18731] Errow when posting data with "Expect: 100-continue" header via ajp with mod_proxy_ajp in apache Created: 15/May/12  Updated: 18/May/12  Resolved: 18/May/12

Status: Resolved
Project: glassfish
Component/s: grizzly-kernel
Affects Version/s: 3.1.2_b23
Fix Version/s: None

Type: Bug Priority: Major
Reporter: jsl123 Assignee: oleksiys
Resolution: Fixed Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Ubuntu 11.04


Attachments: Text File failed.txt     Text File working.txt    
Tags: ajp, apache, expect, mod_proxy_ajp

 Description   

Hi, not sure if this is a grizzly issue or mod_proxy_ajp in apache. Anyway the problem is as follows:
If a client does a POST (presumably other methods do the same) and specifies a Expect header (tested with 100-continue as the value) then apache accepts the headers, marshalls them for ajp and returns a 100-continue response. It then starts to read the body of the message but gets a bad signature from glassfish. This results in glassfish getting a "connection reset from peer" error and return a 500 error back to apache.

I've attached dumps of the process for both a working and not working (with Expects) content.



 Comments   
Comment by jsl123 [ 15/May/12 ]

possible although not great work around are to switch apache to http 1.0 only or ignore the expect header and hope the client doesn't stick to the spec and sends the data straight after the headers without waiting for a response.

Comment by Bas van Gils [ 16/May/12 ]

I experienced the same issue with the Expect header. After thorough investigation we found out that this caused it. As a workaround we strip this header in Apache.

We also had another problem, like described here: http://marc.info/?l=tomcat-user&m=121467240210359.
The suggested solution to add JkOptions +DisableReuse in mod_jk solved it.

Comment by jsl123 [ 16/May/12 ]

I've worked around it by making apache remove the header effectively ignoring it by adding "RequestHeader unset Expect early" to the config. Although this isn't ideal, as it should break any client that sticks to the specifications (luckily most don't) as they should wait for a response before sending the rest of their request body.

Comment by oleksiys [ 18/May/12 ]

fixed

mirror Grizzly issue
http://java.net/jira/browse/GRIZZLY-1267

the patch for GF 3.1.2 can be downloaded here:
http://java.net/jira/browse/GLASSFISH-18446

Comment by jsl123 [ 18/May/12 ]

Looks to work, thanks for your quick turnaround..





[GLASSFISH-18485] Chunking not working when using glassfish 3.1.2 with jk-enabled listener Created: 08/Mar/12  Updated: 09/Mar/12  Resolved: 09/Mar/12

Status: Resolved
Project: glassfish
Component/s: grizzly-kernel
Affects Version/s: 3.1.2
Fix Version/s: None

Type: Bug Priority: Major
Reporter: mkinzel Assignee: oleksiys
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

Debian Squeeze 64Bit
Apache 2.2.16
mod_jk 1.2.32 OR mod_proxy_ajp (comes with Apache)


Tags: 3-1-2, apache, chunking, glassfish, mod_ajp_proxy, mod_jk

 Description   

I have an issue with a JK-enabled listener which is using the chunking feature. It is related to Bug 18341 where a HTTP downgrade directive disabled the chunking feature on apache side.

We just upgraded our glassfish server from 3.1.1 to 3.1.2 and the mod_jk configuration stopped working. All requests larger than one chunk are timing out after 15 seconds. The server response is showing a 2000 on the top of the page and a part of the original page.

workers.properties
# Glassfish and Java configuration
workers.tomcat_home=/var/lib/glassfish/glassfish
workers.java_home=/usr/lib/jvm/java-6-sun/
ps=/
worker.list=test,sindb
# Definition for local worker using AJP 1.3
worker.test.type=ajp13
worker.test.host=localhost
worker.test.port=8010
worker.sindb.type=ajp13
worker.sindb.host=localhost
worker.sindb.port=8009
Apache site config
[...]
    <IfModule mod_jk.c>
        JkMount / test
        JkMount /* test
    </IfModule>
[...]

I don't know if it's a real bug or just a misconfiguration, but the fact it worked in 3.1.1 with chunking enabled confused me.

These scenarios are working:

  • using the 8080 Port of GF without proxy and with chunking
  • using a http proxy (listener has JK disabled) and with chunking
  • using an AJP proxy (mod_proxy_ajp) redirecting to ajp://127.0.0.1:8009 without chunking
  • using the 3.1.1 configuration with mod_jk (see workers.properties) without chunking

When enabling chunking, the mod_proxy_ajp method just shows an empty page.
The mod_jk module produces an error indicating that the connection to the enterprise server is broken.

[Thu Mar 08 12:54:20 2012] [15035:139672345085760] [error] ajp_connection_tcp_get_message::jk_ajp_common.c (1296): wrong message format 0x9293 from 127.0.0.1:8010
[Thu Mar 08 12:54:20 2012] [15035:139672345085760] [error] ajp_get_reply::jk_ajp_common.c (2148): (test) Tomcat is down or network problems. Part of the response has already been sent to the client
[Thu Mar 08 12:54:20 2012] [15035:139672345085760] [info] ajp_service::jk_ajp_common.c (2607): (test) sending request to tomcat failed (recoverable), because of protocol error (attempt=1)
[Thu Mar 08 12:54:21 2012] test test.<DOMAIN> 0.004099
Domain config
<virtual-server id="test" hosts="#####" network-listeners="http-listener-test"></virtual-server>
[...]
<protocol name="http-listener-test">
    <http default-virtual-server="server">
        <file-cache></file-cache>
    </http>
</protocol>
[...]
<network-listener port="8010" protocol="http-listener-test" address="127.0.0.1" transport="tcp" name="http-listener-test" jk-enabled="true" thread-pool="http-thread-pool"></network-listener>
[...]
<thread-pool max-thread-pool-size="200" name="http-thread-pool"></thread-pool>

The glassfish log stays empty.



 Comments   
Comment by oleksiys [ 09/Mar/12 ]

pls. try if patch (2 jar files) from issue
http://java.net/jira/browse/GLASSFISH-18446

resolves the problem.
thx.

Comment by mkinzel [ 09/Mar/12 ]

Thanks, the patch fixed the problem.

Comment by oleksiys [ 09/Mar/12 ]

duplicate of #18446





[GLASSFISH-18446] JK listener with Apache + mod_ajp_proxy causes truncated downloads Created: 03/Mar/12  Updated: 05/Oct/12  Resolved: 06/Mar/12

Status: Resolved
Project: glassfish
Component/s: grizzly-kernel
Affects Version/s: 3.1.2_b23
Fix Version/s: 3.1.2.2

Type: Bug Priority: Blocker
Reporter: buddypine Assignee: oleksiys
Resolution: Fixed Votes: 4
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: File ajp_trunc.cap     Text File chrome_dump.txt     Java Archive File grizzly-http-ajp.jar     Java Archive File grizzly-http.jar     Text File mod_jk.log     Text File wget_dump.txt    
Tags: 3_1_2-next, apache, jk, jl-listener, mod_ajp_proxy

 Description   

Since upgrading to 3.1.2 I am experiencing truncated file downloads from my app with GF behind Apache using a lk-listener and Apache mod_ajp_proxy. It seems to be ajp related as downloads complete fully when accessing app directly on GF http port.

With jk downloads truncate at 256Kb, the original file is 700Kb.

This appears in the Apache logs:

ajp_check_msg_header() got bad signature 28e9
ajp_ilink_receive() received bad header
ajp_read_header: ajp_ilink_receive failed
(120007)APR does not understand this error code: proxy: dialog to 192.168.200.44:8009 (ww.mydomain.com) failed

Config:

asadmin create-network-listener --jkenabled true --protocol http-listener-1 --listenerport 8009 jk-listener
ProxyPass / ajp://www.mydomain.com:8009/
ProxyPassReverse / ajp://www.mydomain.com:8009/

Packet capture of failed download attached.



 Comments   
Comment by buddypine [ 03/Mar/12 ]

I have also tried with mod_jk Tomcat Connector and downloads are truncated at 512Kb.
Attaching error log from mod_jk.

Comment by buddypine [ 03/Mar/12 ]

mod_jk log file showing error

Comment by jsl123 [ 03/Mar/12 ]

Similar problem, webapp returning jsp pages works fine in 3.1.1 and when connecting to glassfish directly, but when you use mod_proxy_ajp, browsers time out waiting for the remaining data

Comment by oleksiys [ 05/Mar/12 ]

to buddypine:
sorry, looks like a bug on our side.
pls. try the attached patch (copy it to glassfish3/glassfish/modules folder)

Comment by oleksiys [ 05/Mar/12 ]

to jsl123:
can you pls. also try the patch, if it doesn't help - pls. let us know how we can reproduce the issue.

Comment by christoph.bernhofer [ 05/Mar/12 ]

Patch doesn't work for me. Have the same issue.
Files still truncated

--> Filesizes compared:
theme.css: should be 31.3 kb
primefaces.css: should be 41 kb
jquery.js: should be 299.8 kb
primefaces.js: should be 179.5 kb

WITHOUT AJP PROXY:
GET adminLogin.jsf?loc=en-GB 200 OK 192.168.78.77:8181 3.1 KB 192.168.78.77:8181 16ms
GET theme.css.jsf?ln=primefaces-aristo 200 OK 192.168.78.77:8181 31.3 KB 11ms
GET primefaces.css.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77:8181 41 KB 12ms
GET password.css.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77:8181 1.4 KB 21ms
GET jquery.js.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77:8181 299.8 KB 22ms
GET primefaces.js.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77:8181 179.5 KB 22ms
GET password.js.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77:8181 4.7 KB 205ms
GET iPCP.css 304 Not Modified 192.168.78.77:8181 2 KB 192.168.78.77:8181 15ms

8 Anfragen

562.8 KB

(559.6 KB vom Cache)

WITH AJP PROXY:
GET adminLogin.jsf?loc=en-GB 200 OK 192.168.78.77 1.1 KB 192.168.78.77:443 16ms
GET theme.css.jsf?ln=primefaces-aristo 200 OK 192.168.78.77 0 192.168.78.77:443 16ms
GET primefaces.css.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77 0 192.168.78.77:443 16ms
GET password.css.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77 433 B 5ms
GET jquery.js.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77 0 192.168.78.77:443 47ms
GET primefaces.js.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77 0 192.168.78.77:443 32ms
GET password.js.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77 1.9 KB 8ms
GET iPCP.css 304 Not Modified 192.168.78.77 733 B 192.168.78.77:443 16ms
GET primefaces.js.jsf?ln=primefaces&v=3.1.1 200 OK 192.168.78.77 0 192.168.78.77:443 16ms

9 Anfragen

4.1 KB

(3 KB vom Cache)

Comment by buddypine [ 05/Mar/12 ]

@oleksiys - thanks the patch does work for me.

Comment by oleksiys [ 06/Mar/12 ]

fixed in Grizzly
http://java.net/jira/browse/GRIZZLY-1213

Comment by oleksiys [ 06/Mar/12 ]

@jsl123
@christoph.bernhofer

can you pls. create a separate issue and provide more data, logs etc. Cause w/ the patch I'm not able to reproduce truncate issue (tried both secure and plain connections).

Comment by oleksiys [ 06/Mar/12 ]

fix will be available in the next 3.1.x release

Comment by rainerfrey [ 06/Mar/12 ]

Will that be a regular several-month release cycle, or is there a chance for a quick release with this fix? AFAIS this is a general problem with Glassfish and JK, and in that case it will keep us from upgrading to 3.1.2.

Or can the circumstances be narrowed down to more special configuration than using a jk-listener in general?

Comment by oleksiys [ 06/Mar/12 ]

Normally we upgrade Grizzly as part of GF release cycle or as patch (which we provided).
I can try to investigate if we can make Grizzly upgrade using GF update tool...

Comment by oleksiys [ 06/Mar/12 ]

changing priority and module

Comment by oleksiys [ 06/Mar/12 ]

@jsl123
@christoph.bernhofer

guys, wanted to ask you to give me more info on your usecases, so we can fix and deliver updates asap.

thanks.

Comment by christoph.bernhofer [ 06/Mar/12 ]

Hi oleksiys

My Application is a JSF2 WAR Application behind Apache 2.2. mod_proxy_ajp.

Created with
asadmin create-threadpool --minthreadpoolsize 5 --maxthreadpoolsize 150 jk-thread-pool
asadmin create-network-listener --protocol http-listener-1 --listenerport 8091 --jkenabled true --threadpool jk-thread-pool jk-connector

and

ProxyPass /iPCP ajp://localhost:8091/iPCP
ProxyPassReverse /iPCP ajp://localhost:8091/iPCP

works flawless with glassfish 3.1.1 in same configuration

updated now Apache ond Debian squeeze x64 to apache/2.2.16 (Debian) PHP/5.3.3-7+squeeze1 with Suhosin-Patch mod_python/3.3.1 Python/2.6.6 mod_ssl/2.2.16 OpenSSL/0.9.8o mod_perl/2.0.4 Perl/v5.10.1 configured

but this hasn't changed anything.

error.log apache2:

ajp_check_msg_header() got bad signature 6575
[Mon Mar 05 14:14:22 2012] [error] ajp_ilink_receive() received bad header
[Mon Mar 05 14:14:22 2012] [error] ajp_read_header: ajp_ilink_receive failed
[Mon Mar 05 14:14:22 2012] [error] (120007)APR does not understand this error code: proxy: dialog to 127.0.0.1:8091 (localhost) failed
[Mon Mar 05 14:14:23 2012] [error] [client 192.168.178.14] File does not exist: /var/www/favicon.ico
[Mon Mar 05 14:14:23 2012] [error] [client 192.168.178.14] File does not exist: /var/www/favicon.ico
[Mon Mar 05 14:14:23 2012] [error] [client 192.168.178.14] File does not exist: /var/www/favicon.ico
[Mon Mar 05 14:15:06 2012] [error] [client 192.168.178.14] proxy: error processing end, referer: http://192.168.78.77/iPCP/admin/adminLogin.jsf?loc=en-GB
[Mon Mar 05 14:15:06 2012] [error] [client 192.168.178.14] proxy: error processing body. Client aborted connection., referer: http://192.168.78.77/iPCP/admin/adminLogin.jsf?loc=en-GB
[Mon Mar 05 14:15:16 2012] [error] ajp_check_msg_header() got bad signature 6575
[Mon Mar 05 14:15:16 2012] [error] ajp_ilink_receive() received bad header
[Mon Mar 05 14:15:16 2012] [error] ajp_read_header: ajp_ilink_receive failed

which more info do you need?

Christoph

Comment by oleksiys [ 06/Mar/12 ]

can you pls. attach the app, or better very reduced version of the app, so I'll be able to debug the problem.

Thanks.

Comment by rainerfrey [ 07/Mar/12 ]

An uĆ¼date via updatetool would be great! Thank you.

Comment by christoph.bernhofer [ 07/Mar/12 ]

Hi oleksiys

I just tried withthe Primefces showcase App.
Same issue. Glassfish 3.1.1. same configuration, same Apache --> works flawless
Glassfish 3.1.2 don't work with proxy, Without proxy it works
I tried to access the App via mod_ssl at Apache at 443 and ajp behind as written above.

Here is the Link to the sample war file:

http://repository.primefaces.org/org/primefaces/prime-showcase/1.0.0-SNAPSHOT/prime-showcase-1.0.0-SNAPSHOT.war

Thx

Christoph

Comment by jsl123 [ 07/Mar/12 ]

Hi guys, sorry didn't get updates about this and was distracted. Trying patch now. Will report on progress.

Comment by oleksiys [ 07/Mar/12 ]

Hi Christoph,

what exactly doesn't work in that app? Cause I'm able to load it in a browser and go throw couple of menu items w/o problems.

Thanks.

Comment by christoph.bernhofer [ 07/Mar/12 ]

Hi oleksiys

Now I get a complete timeout of the whole App. App is not loaded via proxy.

Can you plese tell me your exact versions for Apache, Java...
have you tried also via SSL?

Tx

Christoph

Comment by oleksiys [ 07/Mar/12 ]

I tried mod_ssl and plain, both work fine.

Apache 2.2.17:

ProxyPass /prime-showcase-1.0.0-SNAPSHOT ajp://localhost:8009/prime-showcase-1.0.0-SNAPSHOT retry=0 ttl=30
ProxyPassReverse /prime-showcase-1.0.0-SNAPSHOT ajp://localhost:8009/prime-showcase-1.0.0-SNAPSHOT
ProxyPreserveHost on

JDK:

java version "1.6.0_30"
Java(TM) SE Runtime Environment (build 1.6.0_30-b12)
Java HotSpot(TM) 64-Bit Server VM (build 20.5-b03, mixed mode)

Comment by jsl123 [ 07/Mar/12 ]

OK, further investigation.

Ubuntu 11.10 x64
Apache 2.2.20-1ubuntu1.2
Glassfish 3.1.2 with grizzly patch

If I disable mod_deflate in apache it works fine, pages appear as normal, however as soon as I enable mod_deflate, things break.

With mod_deflate:
Using standard wget works fine - no compression used
Using wget with "accept-encoding:gzip" header set works.
Using firefox/chrome doesn't work. Firefox silently shows a blank page however chrome gives us a clue and reports
"Error 321 (net::ERR_INVALID_CHUNKED_ENCODING): Unknown error

This all works fine in 3.1.1

Looking at the net traffic (attached) they are different both in content (should be the same) and also size, the chunked version is bigger. The wget compressed data expands into the same as if compression isn't used.

So it looks like a different bug

Comment by jsl123 [ 07/Mar/12 ]

tcpdump of chrome page fetch

Comment by jsl123 [ 07/Mar/12 ]

tcp dump of wget

Comment by christoph.bernhofer [ 07/Mar/12 ]

Get the same Error 321 (net::ERR_INVALID_CHUNKED_ENCODING): Unknown error
Deactiveated now mod_deflate --> works

Comment by oleksiys [ 07/Mar/12 ]

thank you guys, i'll investigate that and let you know asap.

Comment by oleksiys [ 07/Mar/12 ]

additional patch

Comment by oleksiys [ 07/Mar/12 ]

guys, can you pls. try to apply another jar (attached) additionally to one which had been attached before?
thx.

Comment by christoph.bernhofer [ 07/Mar/12 ]

Wworks for me with an without mod_deflate!

Great Work, thank you

Comment by jsl123 [ 07/Mar/12 ]

Looks to work for me as well, with mod_deflate.

Will do more testing and post if I find anything else..

good work, Cheers

Comment by jsl123 [ 08/Mar/12 ]

One thing I've noticed and don't think it is expected, but wanted to check before I file a bug? With 3.1.2 when we use HttpServletRequest.getRemoteAddr/Host it returns 127.0.0.1 when using mod_proxy_ajp and apache. With 3.1.1 it returns the address of the client.
I assume this is a bug

Comment by oleksiys [ 08/Mar/12 ]

ok, will check that.

thanks.

Comment by oleksiys [ 09/Mar/12 ]

fix for getRemoteXXX()

Comment by oleksiys [ 09/Mar/12 ]

attached the grizzly-http-ajp.jar with the getRemoteAddr/Host fix.
thanks!

Comment by jsl123 [ 09/Mar/12 ]

Cheers, looks to have fixed it. Would it be possible to push this via the update-tool?

Thanks

Comment by oleksiys [ 09/Mar/12 ]

thank you for confirming!

w/ update tool, we're still investigating this...

Comment by AndrewJames [ 18/Mar/12 ]

I faced the same issue - very happy to see this patch, which resolved the problem - thank you. A life-saver (figuratively speaking).

Comment by oleksiys [ 29/Mar/12 ]

internal bugdb# 13902008.

Comment by oleksiys [ 25/Apr/12 ]

update the patch to fix issue
http://java.net/jira/browse/GRIZZLY-1254

Comment by jsl123 [ 02/May/12 ]

Although the download truncation seems to have been fixed, it looks like we are getting an upload truncation issue. One of my clients is posting files to our server which all worked fine with 3.1.1, but after upgrading and applying the above patches, it bombs out part way through the transfer.

Small files work, but larger ones don't. In apache I get
[Tue May 01 15:06:32 2012] [debug] mod_proxy_ajp.c(273): proxy: data to read (max 8186 at 4)
[Tue May 01 15:06:32 2012] [debug] mod_proxy_ajp.c(288): proxy: got 1448 bytes of data
[Tue May 01 15:06:32 2012] [error] ajp_check_msg_header() got bad signature 4854
[Tue May 01 15:06:32 2012] [error] ajp_ilink_receive() received bad header
[Tue May 01 15:06:32 2012] [error] ajp_read_header: ajp_ilink_receive failed
[Tue May 01 15:06:32 2012] [error] (120007)APR does not understand this error code: proxy: read response failed from 127.0.0.1:8009 (localhost)
[Tue May 01 15:06:32 2012] [debug] proxy_util.c(2029): proxy: AJP: has released connection for (localhost)
[Tue May 01 15:06:32 2012] [debug] mod_headers.c(756): headers: ap_headers_output_filter()
[Tue May 01 15:06:32 2012] [debug] mod_dumpio.c(142): mod_dumpio: dumpio_out

which then results in a 500 error from the server ultimately being returned.

John

Comment by oleksiys [ 04/May/12 ]

Did you try the latest grizzly-http-ajp.jar I attached recently?
Does this problem occur all the time you try to upload files? Do you see anything interesting in the Glassfish server.log?

thx.

Comment by jsl123 [ 04/May/12 ]

I've used the file version from yesterday which was the latest, I'll try and do some more tests to narrow down the problem.
Thanks

Comment by oleksiys [ 14/May/12 ]

any updates?

thx.

Comment by jsl123 [ 15/May/12 ]

Hi, sorry for the delay. I've done some more testing and doesn't appear to be a truncation issue as such, although it might be related. I'm not sure if this is a bug in the grizzly ajp code or apaches mod_proxy_ajp. I've created a new issue for this:
http://java.net/jira/browse/GLASSFISH-18731

Thanks

John

Comment by oleksiys [ 02/Jun/12 ]

update grizzly-http-ajp.jar , which has to have a fix for
http://java.net/jira/browse/GRIZZLY-1276

Comment by bland999 [ 02/Jun/12 ]

The original issue of truncated transmissions is biting my organization (healthcare, 14000+ employees) pretty badly now. We recently upgraded to Glassfish 3.1.2 and we are trying to move away from a very expensive commercial server to this excellent open source choice.

However, this particular issue is a major stopper for us... is there any chance to please roll this fix into an update through the "updatetool" interface?

(We are running the Oracle supported release by the way.)

Thank you!

Comment by benjamin_m [ 08/Jun/12 ]

Ran into similar issue for content generated by Servlets behind mod_jk .
Fix was to remove response.setContentLength() and add "chunked" in HTTP header. Otherwise HTTP chunked data would get truncated for any response bigger than 512KB. Make sure chunked encoding is enable in your Glassfish listeners.

Comment by bland999 [ 13/Jun/12 ]

Chunked encoding is already enabled for the JK listener that we created. And also for the existing HTTP listeners... so I don't think this was the issue.

Comment by benjamin_m [ 13/Jun/12 ]

Having JK listener enabled for chunked encoding is not enough. If your servlet/producer sets the content length then the transfer will be truncated over 512KB.
That part takes its roots in the principle of chunking in HTTP 1.1 against HTTP 1.0 but I don't know if it's an actual error from the GRIZZLY implementation to by pass the chunked setting if setContentLength() is used.

Comment by oleksiys [ 13/Jun/12 ]

@bland999: just to make sure, do you see any issues after applying the patch (2 jar files attached here)? Thanks.

Comment by bland999 [ 14/Jun/12 ]

Thank you both (benjamin_m and oleksiys) for trying to help.

To oleksiys in particular, may I respectfully quote you in an earlier comment: "I can try to investigate if we can make Grizzly upgrade using GF update tool..."

This is actually important to my organization, as they are not very comfortable with open source (this is the first major installation in 30 years to give you an idea), so I was politely hoping that there would be an official release through the update toolset as opposed to applying a patch.

I apologize to request this, but even though I personally am an open source user for many years (I built my first Slackware distribution back in the mid-90's), there is a culture that I am trying to change here. I am sure my organization would be thrilled to see these patches "automagically" appear through updatetool.

Just my two cents, and thanks for taking it into consideration please.

Comment by tmpsa [ 17/Jun/12 ]

I can also confirm that the patched jar files solves the problem. I also got a broken connection to Apache after upgrading GF from 3.1.1 to 3.1.2 . Very frustrating! Thanks for the fix, you saved my day!!

I'll second the suggestion that these kind of critical patches should be distributed, e.g. at the GF 3.1.2 download page.

Comment by oleksiys [ 18/Jun/12 ]

latest patch for fix
http://java.net/jira/browse/GRIZZLY-1284
"AJP connector can not recover after unexpected EOF"

Comment by tmpsa [ 14/Aug/12 ]

I suddenly get get an intense stream of SEVERE loggings, all identical. Same ThreadID, too. See below.
I run GF behind Apache, and have installed the patched jar files (which helped fix the file download issue).

I don't know if this is related, or perhaps another issue?

[#|2012-08-14T10:06:48.961+0200|SEVERE|glassfish3.1.2|com.sun.grizzly.config.GrizzlyServiceListener|_ThreadID=25;_ThreadName=Thread-2;|GRIZZLY0051: ProcessorTask exception.
java.lang.IllegalStateException: Invalid packet magic number: 4745 pos=0lastValid=54 end=0
at com.sun.grizzly.http.ajp.AjpInputBuffer.readAjpMessageHeader(AjpInputBuffer.java:85)
at com.sun.grizzly.http.ajp.AjpProcessorTask.parseRequest(AjpProcessorTask.java:107)
at com.sun.grizzly.http.ProcessorTask.doProcess(ProcessorTask.java:706)
at com.sun.grizzly.http.ProcessorTask.process(ProcessorTask.java:1045)
at com.sun.grizzly.http.DefaultProtocolFilter.execute(DefaultProtocolFilter.java:228)
at com.sun.grizzly.DefaultProtocolChain.executeProtocolFilter(DefaultProtocolChain.java:137)
at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:104)
at com.sun.grizzly.DefaultProtocolChain.execute(DefaultProtocolChain.java:90)
at com.sun.grizzly.http.HttpProtocolChain.execute(HttpProtocolChain.java:79)
at com.sun.grizzly.ProtocolChainContextTask.doCall(ProtocolChainContextTask.java:54)
at com.sun.grizzly.SelectionKeyContextTask.call(SelectionKeyContextTask.java:59)
at com.sun.grizzly.ContextTask.run(ContextTask.java:71)
at com.sun.grizzly.util.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:532)
at com.sun.grizzly.util.AbstractThreadPool$Worker.run(AbstractThreadPool.java:513)
at java.lang.Thread.run(Thread.java:662)

#]
Comment by oleksiys [ 14/Aug/12 ]

That's interesting, may be you try to send plain HTTP request to the AJP port?
Cause instead of AJP protocol magic 0x1234 we read 0x4745, which corresponds to characters "GE", which is probably part of "GET ...."

Comment by robbob [ 27/Aug/12 ]

We are having the same exact issue (same exception & magic number 4745) running GF behind Apache as well. The problem is random, and we have not been able to replicate it consistently. We will go a week or more without any issues, and then when it does occur, it continues occurring for every single request from that point on until the GF domain is restarted. We upgraded to GF 3.1.2.2 hoping that would clear up the issue, but it didn't

Comment by oleksiys [ 27/Aug/12 ]

is it possible to capture tcp traffic (for example using wireshark) when you see this issue?
it really looks like plain HTTP messages come to AJP port, but i might be wrong.

thx.

Comment by oleksiys [ 05/Oct/12 ]

ajp related update for GF 3.1.2.2
http://java.net/jira/browse/GRIZZLY-1340





[GLASSFISH-16721] MS1042: failed to send heartbeatmessage with state=aliveandready to group Created: 24/May/11  Updated: 25/May/11  Resolved: 25/May/11

Status: Closed
Project: glassfish
Component/s: group_management_service
Affects Version/s: 3.1
Fix Version/s: None

Type: Bug Priority: Major
Reporter: sebglon Assignee: Joe Fialli
Resolution: Incomplete Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified
Environment:

ubuntu, glassfish 3.1, apache 2.2.1, mod_jk 1.2.26


Tags: apache, glassfish, ioexception, mod_jk, shoallogger

 Description   

I have an Apache and glassfish with mod_jk.
Many times, I have an error http 500 when i request my apache.

On my log, i have always this line
[#|2011-05-23T19:54:19.749+0200|WARNING|glassfish3.1|ShoalLogger|_ThreadID=11;_ThreadName=Thread-1;|GMS1042: failed to send heartbeatmessage with state=aliveandready to group autre-voyage. Reason: IOException:Operation not permitted|#]

For info, start log:

19-May-2011 23:10:42 com.sun.enterprise.admin.launcher.GFLauncherLogger info
INFO: JVM invocation command line:
/usr/lib/jvm/java-6-openjdk/bin/java
-cp
/opt/glassfish3/glassfish/modules/glassfish.jar
-XX:+UnlockDiagnosticVMOptions
-XX:MaxPermSize=192m
-XX:+AggressiveOpts
-XX:NewRatio=2
-XX:+UseParallelGC
-Xmx512m
-Xmn192m
-javaagent:/opt/glassfish3/glassfish/lib/monitor/btrace-agent.jar=unsafe=true,noServer=true
-server
-Dosgi.shell.telnet.maxconn=1
-Djdbc.drivers=org.apache.derby.jdbc.ClientDriver
-Dfelix.fileinstall.disableConfigSave=false
-Dfelix.fileinstall.dir=/opt/glassfish3/glassfish/modules/autostart/
-Djavax.net.ssl.keyStore=/opt/glassfish3/glassfish/domains/domain1/config/keystore.jks
-Dosgi.shell.telnet.port=6666
-Djava.security.policy=/opt/glassfish3/glassfish/domains/domain1/config/server.policy
-Dfelix.fileinstall.log.level=2
-Dfelix.fileinstall.poll=5000
-Dcom.sun.aas.instanceRoot=/opt/glassfish3/glassfish/domains/domain1
-Dosgi.shell.telnet.ip=127.0.0.1
-Dcom.sun.enterprise.config.config_environment_factory_class=com.sun.enterprise.config.serverbeans.AppserverConfigEnvironmentFactory
-Djava.endorsed.dirs=/opt/glassfish3/glassfish/modules/endorsed:/opt/glassfish3/glassfish/lib/endorsed
-Dcom.sun.aas.installRoot=/opt/glassfish3/glassfish
-Djava.ext.dirs=/usr/lib/jvm/java-6-openjdk/lib/ext:/usr/lib/jvm/java-6-openjdk/jre/lib/ext:/opt/glassfish3/glassfish/domains/domain1/lib/ext
-Dfelix.fileinstall.bundles.startTransient=true
-Dfelix.fileinstall.bundles.new.start=true
-Djavax.net.ssl.trustStore=/opt/glassfish3/glassfish/domains/domain1/config/cacerts.jks
-Dorg.glassfish.additionalOSGiBundlesToStart=org.apache.felix.shell,org.apache.felix.gogo.runtime,org.apache.felix.gogo.shell,org.apache.felix.gogo.command
-Dcom.sun.enterprise.security.httpsOutboundKeyAlias=s1as
-DANTLR_USE_DIRECT_CLASS_LOADING=true
-Djava.security.auth.login.config=/opt/glassfish3/glassfish/domains/domain1/config/login.conf
Dgosh.args=-nointeractive
-Djava.library.path=/opt/glassfish3/glassfish/lib:/usr/lib/jvm/java-6-openjdk/jre/lib/amd64/server:/usr/lib/jvm/java-6-openjdk/jre/lib/amd64:/usr/lib/jvm/java-6-openjdk/lib/amd64:/usr/java/packages/lib/amd64:/usr/lib/jni:/lib:/usr/lib
com.sun.enterprise.glassfish.bootstrap.ASMain
-domainname
domain1
-asadmin-args
-host,,,localhost,,,port,,,4848,,,secure=false,,,terse=false,,,echo=false,,,interactive=true,,,start-domain,,,verbose=false,,,debug=false,,,-domaindir,,,/opt/glassfish3/glassfish/domains,,,domain1
-instancename
server
-verbose
false
-debug
false
-asadmin-classpath
/opt/glassfish3/glassfish/modules/admin-cli.jar
-asadmin-classname
com.sun.enterprise.admin.cli.AsadminMain
-upgrade
false
-type
DAS
-domaindir
/opt/glassfish3/glassfish/domains/domain1
-read-stdin
true
19-May-2011 23:10:42 com.sun.enterprise.admin.launcher.GFLauncherLogger info
INFO: Successfully launched in 8 msec.
[#|2011-05-19T23:11:11.590+0200|INFO|glassfish3.1|null|_ThreadID=1;_ThreadName=Thread-1;|Running GlassFish Version: GlassFish Server Open Source Edition 3.1 (build 43)|#]

[#|2011-05-19T23:11:11.821+0200|INFO|glassfish3.1|javax.org.glassfish.gms.org.glassfish.gms|_ThreadID=1;_ThreadName=Thread-1;|GMSAD1005: Member server joined group autre-voyage|#]

[#|2011-05-19T23:11:11.828+0200|INFO|glassfish3.1|javax.org.glassfish.gms.org.glassfish.gms|_ThreadID=1;_ThreadName=Thread-1;|GMSAD1004: Started GMS for instance server in group autre-voyage|#]

[#|2011-05-19T23:11:11.882+0200|INFO|glassfish3.1|javax.org.glassfish.gms.org.glassfish.gms|_ThreadID=1;_ThreadName=Thread-1;|GMSAD1005: Member server joined group evasion|#]

[#|2011-05-19T23:11:11.883+0200|INFO|glassfish3.1|javax.org.glassfish.gms.org.glassfish.gms|_ThreadID=1;_ThreadName=Thread-1;|GMSAD1004: Started GMS for instance server in group evasion|#]

[#|2011-05-19T23:11:12.117+0200|INFO|glassfish3.1|javax.enterprise.system.core.com.sun.enterprise.v3.services.impl|_ThreadID=59;_ThreadName=Thread-1;|Grizzly Framework 1.9.31 started in: 76ms - bound to [0.0.0.0:4848]|#]

[#|2011-05-19T23:11:12.117+0200|INFO|glassfish3.1|javax.enterprise.system.core.com.sun.enterprise.v3.services.impl|_ThreadID=56;_ThreadName=Thread-1;|Grizzly Framework 1.9.31 started in: 87ms - bound to [0.0.0.0:8181]|#]

[#|2011-05-19T23:11:12.112+0200|INFO|glassfish3.1|javax.enterprise.system.core.com.sun.enterprise.v3.services.impl|_ThreadID=57;_ThreadName=Thread-1;|Grizzly Framework 1.9.31 started in: 32ms - bound to [0.0.0.0:7676]|#]

[#|2011-05-19T23:11:12.112+0200|INFO|glassfish3.1|javax.enterprise.system.core.com.sun.enterprise.v3.services.impl|_ThreadID=58;_ThreadName=Thread-1;|Grizzly Framework 1.9.31 started in: 49ms - bound to [0.0.0.0:3700]|#]

[#|2011-05-19T23:11:12.140+0200|INFO|glassfish3.1|javax.enterprise.system.core.com.sun.enterprise.v3.admin.adapter|_ThreadID=1;_ThreadName=Thread-1;|The Admin Console is already installed, but not yet loaded.|#]

[#|2011-05-19T23:11:12.556+0200|INFO|glassfish3.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=1;_ThreadName=Thread-1;|WEB0170: Apache mod_jk/jk2 attached to virtual-server [server] listening on port [8,080]|#]

[#|2011-05-19T23:11:12.560+0200|INFO|glassfish3.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=1;_ThreadName=Thread-1;|WEB0169: Created HTTP listener [http-listener-2] on host/port [0.0.0.0:8181]|#]

[#|2011-05-19T23:11:12.567+0200|INFO|glassfish3.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=1;_ThreadName=Thread-1;|WEB0169: Created HTTP listener [admin-listener] on host/port [0.0.0.0:4848]|#]

[#|2011-05-19T23:11:12.596+0200|INFO|glassfish3.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=1;_ThreadName=Thread-1;|WEB0171: Created virtual server [server]|#]

[#|2011-05-19T23:11:12.599+0200|INFO|glassfish3.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=1;_ThreadName=Thread-1;|WEB0171: Created virtual server [__asadmin]|#]

[#|2011-05-19T23:11:13.015+0200|INFO|glassfish3.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=1;_ThreadName=Thread-1;|WEB0172: Virtual server [server] loaded default web module []|#]

[#|2011-05-19T23:11:13.117+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAutreVoyage worker|#]

[#|2011-05-19T23:11:13.120+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAutreVoyage worker|#]

[#|2011-05-19T23:11:13.120+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAdmin worker|#]

[#|2011-05-19T23:11:13.121+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAdmin worker|#]

[#|2011-05-19T23:11:13.121+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfEvasion worker|#]

[#|2011-05-19T23:11:13.121+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAutreVoyage worker|#]

[#|2011-05-19T23:11:13.121+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAdmin worker|#]

[#|2011-05-19T23:11:13.122+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfEvasion worker|#]

[#|2011-05-19T23:11:13.122+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAutreVoyage worker|#]

[#|2011-05-19T23:11:13.122+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAutreVoyage worker|#]

[#|2011-05-19T23:11:13.122+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAutreVoyage worker|#]

[#|2011-05-19T23:11:13.123+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAutreVoyage worker|#]

[#|2011-05-19T23:11:13.123+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfEvasion worker|#]

[#|2011-05-19T23:11:13.123+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAutreVoyage worker|#]

[#|2011-05-19T23:11:13.124+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAutreVoyage worker|#]

[#|2011-05-19T23:11:13.124+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker worker|#]

[#|2011-05-19T23:11:13.124+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAdmin worker|#]

[#|2011-05-19T23:11:13.124+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfEvasion worker|#]

[#|2011-05-19T23:11:13.124+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAdmin worker|#]

[#|2011-05-19T23:11:13.125+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfEvasion worker|#]

[#|2011-05-19T23:11:13.138+0200|WARNING|glassfish3.1|org.apache.tomcat.util.threads.ThreadPool|_ThreadID=10;_ThreadName=Thread-1;|threadpool.max_threads_too_low|#]

[#|2011-05-19T23:11:14.206+0200|INFO|glassfish3.1|javax.enterprise.system.core.com.sun.enterprise.v3.services.impl|_ThreadID=1;_ThreadName=Thread-1;|core.start_container_done|#]

and my mod_jk config:
glassfish-jk.properties file -->

  1. Define 1 real worker using ajp13
    worker.list=gfEvasion, gfAdmin, gfAutreVoyage
  1. Set properties for worker1 (ajp13)
    worker.gfAdmin.type=ajp13
    worker.gfAdmin.host=localhost
    worker.gfAdmin.port=8080
    worker.gfAdmin.lbfactor=25
    worker.gfAdmin.cachesize=10
    #worker.gfAdmin.cache_timeout=600
    #worker.gfAdmin.socket_keepalive=1
    #worker.gfAdmin.socket_timeout=300
  1. Set properties for worker1 (ajp13)
    worker.gfEvasion.type=ajp13
    worker.gfEvasion.host=localhost
    worker.gfEvasion.port=28081
    worker.gfEvasion.lbfactor=25
    worker.gfEvasion.cachesize=10
    #worker.gfEvasion.cache_timeout=600
    #worker.gfEvasion.socket_keepalive=1
    #worker.gfEvasion.socket_timeout=300

worker.gfAutreVoyage.type=ajp13
worker.gfAutreVoyage.host=localhost
worker.gfAutreVoyage.port=28080
worker.gfAutreVoyage.lbfactor=25
worker.gfAutreVoyage.cachesize=10
worker.gfAutreVoyage.cache_timeout=600
worker.gfAutreVoyage.socket_keepalive=1
worker.gfAutreVoyage.socket_timeout=300
worker.gfAutreVoyage.connection_pool_timeout=600

My virtual host config: JkMount /* gfAutreVoyage

and my httpd.conf

JkWorkersFile /opt/glassfish3/glassfish/domains/domain1/config/glassfish-jk.properties

  1. Where to put jk logs
    JkLogFile /var/log/apache2/mod_jk.log
  2. Set the jk log level [debug/error/info]
    JkLogLevel debug
  3. Select the log format
    JkLogStampFormat "[%a %b %d %H:%M:%S %Y] "
  4. JkOptions indicate to send SSL KEY SIZE,
    JkOptions +ForwardKeySize +ForwardURICompat -ForwardDirectories
  5. JkRequestLogFormat set the request format
    JkRequestLogFormat "%w %V %T"


 Comments   
Comment by Nazrul [ 24/May/11 ]

User is using openJDK. Perhaps it would be a good idea to try HotSpot (Sun) JDK from here: http://www.oracle.com/technetwork/java/javase/downloads/index.html

Comment by Joe Fialli [ 25/May/11 ]

These comments only pertain to following reported log message and the subject of this issue.

[#|2011-05-23T19:54:19.749+0200|WARNING|glassfish3.1|ShoalLogger|_ThreadID=11;_ThreadName=Thread-1;|GMS1042: failed to send heartbeatmessage with state=aliveandready to group autre-voyage. Reason: IOException:Operation not permitted|#]

Shoal GMS requires UDP multicast to be configured properly to be used between glassfish clustered instances.
The above failure indicates that multicast may not be configured to be allowed at the OS networking layer.

The following link provides guidance on verifying UDP multicast is configured properly.
http://blogs.oracle.com/bobby/entry/validating_multicast_transport_where_d

The reported failure is a network or security configuration issue that is not allowing the UDP multicast operation
to succeed so this issue will be marked invalid.

*******

The following error message is not a GMS issue.

[#|2011-05-19T23:11:13.117+0200|SEVERE|glassfish3.1|org.apache.jk.server.JkMain|_ThreadID=10;_ThreadName=Thread-1;|No class name for worker.gfAutreVoyage worker|#]

It should be filed as different issue with a different subcomponent.

Comment by Joe Fialli [ 25/May/11 ]

Marking this issue as incomplete since information was not provided that illustrated that
UDP multicast was verified to be working properly. The reported failure "Operation invalid"
on sending a UDP multicast message indicates that UDP multicast is not enabled.

Following the directions on this
link: http://blogs.oracle.com/bobby/entry/validating_multicast_transport_where_d
should resolve the network configuration issue.

If it does not, please submit "ifconfig -a" output (or equivalent if OS does not support that command),
the DAS server.log with ShoalLogger log level of CONFIG. (provides what network addresses and ports are being used)

% asadmin set-log-levels ShoalLogger=CONFIG

Run the above before creating cluster.

The ifconfig output should have "MULTICAST" on a line similar to following:
en0: flags=8863<UP,BROADCAST,SMART,RUNNING,SIMPLEX,MULTICAST> mtu 1500





Generated at Thu Sep 29 18:34:17 UTC 2016 using JIRA 6.2.3#6260-sha1:63ef1d6dac3f4f4d7db4c1effd405ba38ccdc558.