12 Replies Latest reply on Apr 12, 2011 10:28 AM by joaocunhalopes

    Unexpected Behaviour. Unable to go live.

    joaocunhalopes

      First, this is what I belive that should not happen:

       

      Looking at the Apache logs, for two subsequent requests at the same context (one request is OK the other is showing a 404 Page Not Found error)

       

      This is the Apache access log: Green is expected. Red is unexpected:

       

      192.168.120.115 - - [07/Apr/2011:10:29:02 +0100] "POST /scpcqaw/SurveyServiceWS HTTP/1.1" 200 2326

      192.168.120.115 - - [07/Apr/2011:10:29:03 +0100] "POST /scpcqaw/SurveyServiceWS HTTP/1.1" 404 -

       

       

      This is the Apache error log (in debug mode) for both requests. Again, I have marked green what it's expected and red what I consider to be unexpected:

       

      [Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(659): proxy: AJP: serving URL ajp://192.168.150.43:8309/scpcqaw/SurveyServiceWS

      [Thu Apr 07 10:29:02 2011] [debug] proxy_util.c(2011): proxy: AJP: has acquired connection for (192.168.150.43)

      [Thu Apr 07 10:29:02 2011] [debug] proxy_util.c(2067): proxy: connecting ajp://192.168.150.43:8309/scpcqaw/SurveyServiceWS to 192.168.150.43:8309

      [Thu Apr 07 10:29:02 2011] [debug] proxy_util.c(2193): proxy: connected /scpcqaw/SurveyServiceWS to 192.168.150.43:8309

      [Thu Apr 07 10:29:02 2011] [debug] ajp_utils.c(31): Into ajp_handle_cping_cpong

      [Thu Apr 07 10:29:02 2011] [debug] ajp_utils.c(102): ajp_handle_cping_cpong: Done

      [Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(224): Into ajp_marshal_into_msgb

      [Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[0] [SOAPAction] = [""]

      [Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[1] [Accept] = [text/xml, multipart/related, text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2]

      [Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[2] [Content-Type] = [text/xml;charset="utf-8"]

      [Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[3] [User-Agent] = [JAX-WS RI 2.1.3-b02-]

      [Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[4] [Host] = [192.168.150.6]

      [Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[5] [Connection] = [keep-alive]

      [Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[6] [Content-Length] = [529]

      [Thu Apr 07 10:29:02 2011] [debug] ajp_header.c(450): ajp_marshal_into_msgb: Done

      [Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(265): proxy: APR_BUCKET_IS_EOS

      [Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(270): proxy: data to read (max 8186 at 4)

      [Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(285): proxy: got 529 bytes of data

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 04

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 04

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(516): ajp_unmarshal_response: status = 200

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(537): ajp_unmarshal_response: Number of headers is = 2

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[0] [X-Powered-By] = [Servlet 2.5; JBoss-5.0/JBossWeb-2.1]

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[1] [Content-Type] = [text/xml;charset=utf-8]

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(609): ajp_unmarshal_response: ap_set_content_type done

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 03

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 03

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 03

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 03

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 05

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 05

      [Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(568): proxy: got response from 192.168.150.43:8309 (192.168.150.43)

      [Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2029): proxy: AJP: has released connection for (192.168.150.43)

      [Thu Apr 07 10:29:03 2011] [debug] mod_proxy_cluster.c(1423): proxy: byrequests balancer DONE (ajp://192.168.150.43:8109)

      [Thu Apr 07 10:29:03 2011] [debug] mod_proxy.c(1015): Running scheme balancer handler (attempt 0)

      [Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(659): proxy: AJP: serving URL ajp://192.168.150.43:8109/scpcqaw/SurveyServiceWS

      [Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2011): proxy: AJP: has acquired connection for (192.168.150.43)

      [Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2067): proxy: connecting ajp://192.168.150.43:8109/scpcqaw/SurveyServiceWS to 192.168.150.43:8109

      [Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2193): proxy: connected /scpcqaw/SurveyServiceWS to 192.168.150.43:8109

      [Thu Apr 07 10:29:03 2011] [debug] ajp_utils.c(31): Into ajp_handle_cping_cpong

      [Thu Apr 07 10:29:03 2011] [debug] ajp_utils.c(102): ajp_handle_cping_cpong: Done

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(224): Into ajp_marshal_into_msgb

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[0] [SOAPAction] = [""]

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[1] [Accept] = [text/xml, multipart/related, text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2]

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[2] [Content-Type] = [text/xml;charset="utf-8"]

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[3] [User-Agent] = [JAX-WS RI 2.1.3-b02-]

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[4] [Host] = [192.168.150.6]

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[5] [Connection] = [keep-alive]

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[6] [Content-Length] = [386]

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(450): ajp_marshal_into_msgb: Done

      [Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(265): proxy: APR_BUCKET_IS_EOS

      [Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(270): proxy: data to read (max 8186 at 4)

      [Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(285): proxy: got 386 bytes of data

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 04

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 04

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(516): ajp_unmarshal_response: status = 404

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(537): ajp_unmarshal_response: Number of headers is = 1

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(599): ajp_unmarshal_response: Header[0] [Content-Length] = [0]

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(687): ajp_read_header: ajp_ilink_received 05

      [Thu Apr 07 10:29:03 2011] [debug] ajp_header.c(697): ajp_parse_type: got 05

      [Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(568): proxy: got response from 192.168.150.43:8109 (192.168.150.43)

      [Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2029): proxy: AJP: has released connection for (192.168.150.43)

       

       

      It's unexpected that the request (I mean, the one with 404 Page Not Found) is routed to

       

      192.168.150.43:8109

       

      The reason why this is unexpected is based on the fact that there is no /scpcqaw context on this IP/port.

       

      Take a look at the mod_cluster manager information:

       

      Node: [1],Name: si_part2_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8209,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 2,Read: 22009,Transfered: 410,Connected: 0,Load: 96

      Node: [2],Name: si_part1_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8109,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 0,Read: 0,Transfered: 0,Connected: 0,Load: 97

      Node: [3],Name: ph_part1_node2,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.44,Port: 8009,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 0,Read: 0,Transfered: 0,Connected: 0,Load: 96

      Node: [4],Name: ph_part1_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8009,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 47,Read: 0,Transfered: 0,Connected: 0,Load: 97

      Node: [5],Name: ne_part1_node2,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.44,Port: 8409,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 1,Read: 0,Transfered: 0,Connected: 0,Load: 96

      Node: [6],Name: ne_part1_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8409,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 1,Read: 0,Transfered: 0,Connected: 0,Load: 98

      Node: [7],Name: pc_part1_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8309,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 84,Read: 1027146,Transfered: 77,Connected: 0,Load: 94

      Vhost: [1:1:1], Alias: localhost

      Vhost: [2:1:2], Alias: localhost

      Vhost: [3:1:3], Alias: localhost

      Vhost: [4:1:4], Alias: localhost

      Vhost: [5:1:5], Alias: localhost

      Vhost: [6:1:6], Alias: localhost

      Vhost: [7:1:7], Alias: localhost

      Context: [1:1:1], Context: /femss, Status: ENABLED

      Context: [3:1:3], Context: /fephn, Status: ENABLED

      Context: [4:1:4], Context: /fephn, Status: ENABLED

      Context: [5:1:5], Context: /load-demo, Status: ENABLED

      Context: [6:1:6], Context: /load-demo, Status: ENABLED

      Context: [7:1:7], Context: /bopcapl, Status: ENABLED

      Context: [7:1:8], Context: /scpcreports, Status: ENABLED

      Context: [2:1:9], Context: /fectt, Status: ENABLED

      Context: [7:1:10], Context: /fepcapl, Status: ENABLED

      Context: [7:1:11], Context: /scpcpsm, Status: ENABLED

      Context: [7:1:12], Context: /scpcqaw, Status: ENABLED

      Context: [7:1:13], Context: /scpcmgu, Status: ENABLED

       

       

      So the question is:

       

      if there is no /scpcqaw context on

       

      Node: [2],Name: si_part1_node1,Balancer: ApacheHttpdBalancer,LBGroup: ,Host: 192.168.150.43,Port: 8109,Type: ajp,Flushpackets: Off,Flushwait: 10,Ping: 10,Smax: 1025,Ttl: 60,Elected: 0,Read: 0,Transfered: 0,Connected: 0,Load: 97

       

      why are there these lines

       

      [Thu Apr 07 10:29:03 2011] [debug] mod_proxy_ajp.c(659): proxy: AJP: serving URL ajp://192.168.150.43:8109/scpcqaw/SurveyServiceWS


      [Thu Apr 07 10:29:03 2011] [debug] proxy_util.c(2067): proxy: connecting ajp://192.168.150.43:8109/scpcqaw/SurveyServiceWS to 192.168.150.43:8109

       

      on the Apache logs?

       

      Any help is welcome!

        • 1. Re: Unexpected Behaviour: Showstopper Bug?
          joaocunhalopes

          Here's the Apache httpd.conf. It may be usefull to check if there is a configuration problem.

           

          ServerRoot "D:/Apache2.2"

           

          ThreadsPerChild 1024

          MaxRequestsPerChild 0

           

          # Module required for Apache startup

          LoadModule authz_host_module modules/mod_authz_host.so

           

          # Modules for Apache content cache

          LoadModule cache_module modules/mod_cache.so

          LoadModule mem_cache_module modules/mod_mem_cache.so

           

          # Apache content cache configuration

          CacheEnable mem /

          #MCacheSize 2 gigabyte = 2097152 kilobyte

          MCacheSize 2097152

          #MCacheMaxObjectCount 2097152 kilobyte / 32 kilobyte = 65536 objects

          MCacheMaxObjectCount 65536

          #MCacheMinObjectSize 64 byte

          MCacheMinObjectSize 64

          #MCacheMaxObjectSize 512 kilobyte = 524288 byte

          MCacheMaxObjectSize 524288

           

          # Apache server-status

          LoadModule status_module modules/mod_status.so

          ExtendedStatus On

           

          # Modules for Apache logging

          LoadModule logio_module modules/mod_logio.so

          LoadModule log_config_module modules/mod_log_config.so

           

          # Apache logging configuration

          ErrorLog "logs/error.log"

          LogLevel info

          LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined

          LogFormat "%h %l %u %t \"%r\" %>s %b" common

          LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %I %O" combinedio

          CustomLog "logs/access.log" common

           

          # Modules for JBoss mod_cluster

          LoadModule proxy_module modules/mod_proxy.so

          LoadModule proxy_ajp_module modules/mod_proxy_ajp.so

          LoadModule slotmem_module modules/mod_slotmem.so

          LoadModule manager_module modules/mod_manager.so

          LoadModule proxy_cluster_module modules/mod_proxy_cluster.so

          LoadModule advertise_module modules/mod_advertise.so

           

          # Virtual host for JBoss mod_cluster (port 6666 will be used to receive information from JBoss servers)

          Listen 192.168.150.6:6666

          <VirtualHost 192.168.150.6:6666>

              KeepAliveTimeout 60

              MaxKeepAliveRequests 0

           

              ManagerBalancerName ApacheHttpdBalancer

              ServerAdvertise Off

           

              <Location />   

                  Order deny,allow

                  Deny from all

                  Allow from 192.168.150.

              </Location>

          </VirtualHost>

           

          # Virtual host for www.xpto.pt

          Listen 192.168.150.6:80

          <VirtualHost *:80>

              <Location /mcm>

                  SetHandler mod_cluster-manager

           

                  Order deny,allow

                  Deny from all

                  Allow from 192.168.120.

              </Location>

           

              <Location /server-status>

                  SetHandler server-status

           

                  Order deny,allow

                  Deny from all

                  Allow from 192.168.120.

              </Location>

           

              <Location /load-demo>

                  Order deny,allow

                  Deny from all

                  Allow from 192.168.120.

              </Location>

          </VirtualHost>

          • 2. Unexpected Behaviour: Bad Configuration or Bug?
            joaocunhalopes

            Anyone?

            This is really a show stopper for a Production environment...

            • 3. Unexpected Behaviour: Bad Configuration or Bug?
              jfclere

              Looks like a having twice the JVMRoute :-(

              To know have is wrong I need the CONFIG and ENABLE-APP messages.

              • 4. Re: Unexpected Behaviour: Bad Configuration or Bug?
                joaocunhalopes

                Here are the JBoss nodes startup files (this is where I'm setting the jvmRoute):

                 

                :cmdStart

                ...

                call "%SVCPATH%\run.bat" -c si_part1_node1 -g si_part1 -b 192.168.150.43 -u 239.255.100.110 -Djboss.service.binding.set=ports-01 -Djboss.messaging.ServerPeerID=1 -Djboss.modcluster.jvmRoute=si_part1_node1 < .r_si_part1_node1.lock >> run_si_part1_node1.log 2>&1

                 

                :waitRun

                ...

                call "%SVCPATH%\run.bat" -c si_part1_node1 -g si_part1 -b 192.168.150.43 -u 239.255.100.110 -Djboss.service.binding.set=ports-01 -Djboss.messaging.ServerPeerID=1 -Djboss.modcluster.jvmRoute=si_part1_node1 < .r_si_part1_node1.lock >> run_si_part1_node1.log 2>&1

                 

                 

                 

                and for the "other" JBoss node:

                 

                 

                 

                :cmdStart

                ...

                call "%SVCPATH%\run.bat" -c pc_part1_node1 -g pc_part1 -b 192.168.150.43 -u 239.255.100.130 -Djboss.service.binding.set=ports-03 -Djboss.messaging.ServerPeerID=1 -Djboss.modcluster.jvmRoute=pc_part1_node1 < .r_pc_part1_node1.lock >> run_pc_part1_node1.log 2>&1

                 

                :waitRun

                ...

                call "%SVCPATH%\run.bat" -c pc_part1_node1 -g pc_part1 -b 192.168.150.43 -u 239.255.100.130 -Djboss.service.binding.set=ports-03 -Djboss.messaging.ServerPeerID=1 -Djboss.modcluster.jvmRoute=pc_part1_node1 < .r_pc_part1_node1.lock >> run_pc_part1_node1.log 2>&1

                 

                 

                 

                As for the CONFIG and ENABLE-APP messages here's what I found on the log, close to 404 error:

                 

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(1644): manager_trans CONFIG (/)

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2287): manager_handler CONFIG (D:/) processing: "JVMRoute=pc_part1_node1&Host=192.168.150.43&Maxattempts=1&Port=8309&StickySessionForce=No&Type=ajp"

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2330): manager_handler CONFIG  OK

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(1644): manager_trans ENABLE-APP (/)

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2287): manager_handler ENABLE-APP (D:/) processing: "JVMRoute=pc_part1_node1&Alias=localhost&Context=%2Fbopcapl"

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2330): manager_handler ENABLE-APP  OK

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(1644): manager_trans ENABLE-APP (/)

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2287): manager_handler ENABLE-APP (D:/) processing: "JVMRoute=pc_part1_node1&Alias=localhost&Context=%2Fscpcreports"

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2330): manager_handler ENABLE-APP  OK

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(1644): manager_trans ENABLE-APP (/)

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2287): manager_handler ENABLE-APP (D:/) processing: "JVMRoute=pc_part1_node1&Alias=localhost&Context=%2Ffepcapl"

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2330): manager_handler ENABLE-APP  OK

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(1644): manager_trans ENABLE-APP (/)

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2287): manager_handler ENABLE-APP (D:/) processing: "JVMRoute=pc_part1_node1&Alias=localhost&Context=%2Fscpcmgu"

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2330): manager_handler ENABLE-APP  OK

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(1644): manager_trans ENABLE-APP (/)

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2287): manager_handler ENABLE-APP (D:/) processing: "JVMRoute=pc_part1_node1&Alias=localhost&Context=%2Fscpcpsm"

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2330): manager_handler ENABLE-APP  OK

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(1644): manager_trans ENABLE-APP (/)

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2287): manager_handler ENABLE-APP (D:/) processing: "JVMRoute=pc_part1_node1&Alias=localhost&Context=%2Fscpcqaw"

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2330): manager_handler ENABLE-APP  OK

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(1644): manager_trans ENABLE-APP (/)

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2287): manager_handler ENABLE-APP (D:/) processing: "JVMRoute=pc_part1_node1&Alias=localhost&Context=%2Ffepcwcm"

                [Thu Apr 07 10:23:37 2011] [debug] mod_manager.c(2330): manager_handler ENABLE-APP  OK

                 

                 

                and

                 

                 

                [Thu Apr 07 10:23:31 2011] [debug] mod_manager.c(1644): manager_trans CONFIG (/)

                [Thu Apr 07 10:23:31 2011] [debug] mod_manager.c(2287): manager_handler CONFIG (D:/) processing: "JVMRoute=si_part1_node1&Host=192.168.150.43&Maxattempts=1&Port=8109&StickySessionForce=No&Type=ajp"

                [Thu Apr 07 10:23:31 2011] [debug] mod_manager.c(2330): manager_handler CONFIG  OK

                [Thu Apr 07 10:23:31 2011] [debug] mod_manager.c(1644): manager_trans ENABLE-APP (/)

                [Thu Apr 07 10:23:31 2011] [debug] mod_manager.c(2287): manager_handler ENABLE-APP (D:/) processing: "JVMRoute=si_part1_node1&Alias=localhost&Context=%2Ffectt"

                [Thu Apr 07 10:23:31 2011] [debug] mod_manager.c(2330): manager_handler ENABLE-APP  OK

                 

                 

                Evrything looks normal to me.

                • 5. Re: Unexpected Behaviour: Bad Configuration or Bug?
                  jfclere

                  hm the CONFIG are OK.

                   

                  Is there a sessionid in the first response?

                  • 6. Re: Unexpected Behaviour: Bad Configuration or Bug?
                    jfclere

                    "[Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(659): proxy: AJP: serving URL ajp://192.168.150.43:8309/scpcqaw/SurveyServiceWS"

                     

                    It would be nice to have the trace before that....


                    • 7. Unexpected Behaviour: Showstopper Bug?
                      joaocunhalopes

                      > Is there a sessionid in the first response?

                       

                      Hum... not sure if I follow your question. This may not be the right answer but:

                      I'll try to use wireshark and check for the HTTP session id of the requests, I dont't think I'll find that on the logs.

                       

                      >"[Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(659): proxy: AJP: serving URL ajp://192.168.150.43:8309/scpcqaw/SurveyServiceWS"

                       

                      >It would be nice to have the trace before that....

                       

                      Ok, I'll post it ASAP.

                      Thank you.

                      • 8. Unexpected Behaviour: Showstopper Bug?
                        jfclere

                        > Is there a sessionid in the first response?

                         

                        The trace of response should contain it too.

                        • 9. Re: Unexpected Behaviour: Showstopper Bug?
                          joaocunhalopes

                          >It would be nice to have the trace before that....

                           

                          Here are the full logs.

                          You can find the 404 error at line number 15200 of the error.log.

                           

                          As for this line

                           

                          >"[Thu Apr 07 10:29:02 2011] [debug] mod_proxy_ajp.c(659): proxy: AJP: serving URL ajp://192.168.150.43:8309/scpcqaw/SurveyServiceWS"

                           

                          it's located at line 15145 of the error.log file.

                           

                          Last friday (2011-04-08) we did some more tests and this behaviour was still present. I'll replicate it again today and look for the session id.

                          Please let me know if you require any further information.

                          Thank you.


                          • 10. Re: Unexpected Behaviour: Showstopper Bug?
                            joaocunhalopes

                            > Is there a sessionid in the first response?

                             

                            >The trace of response should contain it too.

                             

                            From the tests that we did today no session id was detected on the AJP packets that are sent to the JBoss servers.

                            The AJP packets that I am refering to are the ones related to the calls that are made to the context

                             

                            /scpcqaw

                             

                            We did see other AJP packets with session ids. There are some on the logs that I posted. For example, on line 13663:

                             

                            [Thu Apr 07 10:27:19 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[0] [Accept] = [*/*]

                            [Thu Apr 07 10:27:19 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[1] [Referer] = [http://192.168.150.6/bopcapl/app/restricted/accessStatistics.jspx]

                            [Thu Apr 07 10:27:19 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[2] [Accept-Language] = [en-US]

                            [Thu Apr 07 10:27:19 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[3] [User-Agent] = [Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1; Trident/4.0; .NET CLR 2.0.50727; .NET CLR 3.0.4506.2152; .NET CLR 3.5.30729; InfoPath.3)]

                            [Thu Apr 07 10:27:19 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[4] [Accept-Encoding] = [gzip, deflate]

                            [Thu Apr 07 10:27:19 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[5] [If-Modified-Since] = [Wed, 06 Apr 2011 11:38:32 GMT]

                            [Thu Apr 07 10:27:19 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[6] [If-None-Match] = [W/"16810-1302089912000"]

                            [Thu Apr 07 10:27:19 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[7] [Host] = [192.168.150.6]

                            [Thu Apr 07 10:27:19 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[8] [Connection] = [Keep-Alive]

                            [Thu Apr 07 10:27:19 2011] [debug] ajp_header.c(290): ajp_marshal_into_msgb: Header[9] [Cookie] = [JSESSIONID=065E1CC875614D1DD763F0BF2B2A0337.pc_part1_node1]

                             

                            The above (marked red) packet does have a session id but the context is NOT /scpcqaw

                             

                            I'm out of ideas...

                            • 11. Re: Unexpected Behaviour: Showstopper Bug?
                              joaocunhalopes

                              Looking at the logs again and the first line where we "see" that something is not right is this one:

                               

                              [Thu Apr 07 10:29:03 2011] [debug] mod_proxy_cluster.c(1423): proxy: byrequests balancer DONE (ajp://192.168.150.43:8109)

                               

                              The mod_proxy_cluster.c (1423) sounded like a good place to look.

                              The code that prints the above message is below:

                               

                               

                                  if (mycandidate) {

                                      /* Failover in domain */

                                      if (!checked_domain)

                                          apr_table_setn(r->notes, "session-domain-ok", "1");

                                      mycandidate->s->elected++;

                                      ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server,

                                                           "proxy: byrequests balancer DONE (%s)", mycandidate->name);

                                  } else {

                                      ap_log_error(APLOG_MARK, APLOG_DEBUG, 0, r->server,

                                                           "proxy: byrequests balancer FAILED");

                                  }

                                  return mycandidate;

                               

                               

                              So, a few lines up mycandidate->name is "ajp://192.168.150.43:8109" when, IMHO, it should be "ajp://192.168.150.43:8309"

                              I have looked for the places in the code where mycandidate is manipulated and they are not that many.

                               

                              untitled.JPG

                              Any help is appreciated.

                              Thank you.

                              • 12. Unexpected Behaviour. Unable to go live. Bug?
                                joaocunhalopes

                                Changed from 1.1.1 Final to 1.0.9 GA and we are not observing the same behaviour.

                                Maybe jumping into conclusions but the 404s are gone.

                                Will do more tests and post here.

                                Txs.