Bug 1063292 - Wildfly - Illegal controller state
Summary: Wildfly - Illegal controller state
Keywords:
Status: CLOSED WORKSFORME
Alias: None
Product: Fedora
Classification: Fedora
Component: wildfly
Version: 20
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Marek Goldmann
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2014-02-10 12:34 UTC by Juraci Paixão Kröhling
Modified: 2014-02-13 12:36 UTC (History)
2 users (show)

Fixed In Version:
Clone Of:
Environment:
Last Closed: 2014-02-11 13:09:23 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)
server.log (13.48 KB, text/x-log)
2014-02-10 12:34 UTC, Juraci Paixão Kröhling
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1064759 0 unspecified CLOSED wildfly: Upgrade to 8.0.0.Final 2021-02-22 00:41:40 UTC

Internal Links: 1064759

Description Juraci Paixão Kröhling 2014-02-10 12:34:05 UTC
Created attachment 861374 [details]
server.log

Description of problem:

When booting or stopping Wildfly 8 CR1 via systemd, an IllegalStateException happens during shutdown (stop). When this happens, "stop" won't really stop the server, but systemd will think so. Please, see the attached logs.

Version-Release number of selected component (if applicable):
wildfly-8.0.0-0.17.CR1.fc20.noarch , from https://admin.fedoraproject.org/updates/FEDORA-2014-2210/wildfly-8.0.0-0.17.CR1.fc20 (as I was also having the same problem as BZ 1062877)

How reproducible:
100%

Steps to Reproduce:
1. On a clean Fedora 20 installation, install Wildfly from the official repository, then upgrade by installing the one from: https://admin.fedoraproject.org/updates/FEDORA-2014-2210/wildfly-8.0.0-0.17.CR1.fc20
2. Start wildfly (systemctl start wildfly) . 
3. Stop wildfly (systemctl stop wildfly)

Actual results:
The server is still running (verifiable via ps)

Expected results:
The server would shutdown

Additional info:
A Wildfly ZIP bundle on the same machine works fine.

Comment 1 Marek Goldmann 2014-02-11 12:03:04 UTC
I'm looking into this.

Comment 2 Marek Goldmann 2014-02-11 13:09:23 UTC
Sorry, but I cannot reproduce this (see below). I guess it may be some race condition related somehow to the installation. Since I cannot reproduce this issue - I'll close it. BTW: soon 8.0.0.Final will be released.

[root@localhost ~]# rpm -q wildfly
wildfly-8.0.0-0.17.CR1.fc20.noarch
[root@localhost ~]# systemctl status wildfly
wildfly.service - The WildFly Application Server
   Loaded: loaded (/usr/lib/systemd/system/wildfly.service; disabled)
   Active: inactive (dead)

[root@localhost ~]# systemctl start wildfly
[root@localhost ~]# systemctl status wildfly
wildfly.service - The WildFly Application Server
   Loaded: loaded (/usr/lib/systemd/system/wildfly.service; disabled)
   Active: active (running) since wto 2014-02-11 14:05:57 CET; 5s ago
 Main PID: 894 (launch.sh)
   CGroup: /system.slice/wildfly.service
           ├─894 /bin/sh /usr/share/wildfly/bin/launch.sh standalone standalone.xml 0.0.0.0
           ├─895 /bin/sh /usr/share/wildfly/bin/standalone.sh -c standalone.xml -b 0.0.0.0
           └─961 java -D[Standalone] -server -XX:+UseCompressedOops -Xms64m -Xmx512m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true -Dorg.jboss.boot.log.file=/usr/share/wildfly/standalone/log/server.log...

lut 11 14:05:57 localhost.localdomain systemd[1]: Started The WildFly Application Server.
[root@localhost ~]# systemctl stop wildfly
[root@localhost ~]# systemctl status wildfly
wildfly.service - The WildFly Application Server
   Loaded: loaded (/usr/lib/systemd/system/wildfly.service; disabled)
   Active: inactive (dead)

lut 11 14:05:57 localhost.localdomain systemd[1]: Starting The WildFly Application Server...
lut 11 14:05:57 localhost.localdomain systemd[1]: Started The WildFly Application Server.
lut 11 14:06:08 localhost.localdomain systemd[1]: Stopping The WildFly Application Server...
lut 11 14:06:08 localhost.localdomain systemd[1]: Stopped The WildFly Application Server.

Comment 3 Michal Srb 2014-02-11 13:32:24 UTC
I cannot reproduce it either. 8.0.0-0.17.CR1.fc20 update works for me without any problems.

$ rpm -q wildfly
wildfly-8.0.0-0.17.CR1.fc20.noarch

$ lsb_release -a
LSB Version:	:core-4.1-amd64:core-4.1-noarch
Distributor ID:	Fedora
Description:	Fedora release 20 (Heisenbug)
Release:	20
Codename:	Heisenbug


# systemctl status wildfly
wildfly.service - The WildFly Application Server
   Loaded: loaded (/usr/lib/systemd/system/wildfly.service; disabled)
   Active: active (running) since Tue 2014-02-11 14:19:10 CET; 4min 59s ago
 Main PID: 26502 (launch.sh)
   CGroup: /system.slice/wildfly.service
           ├─26502 /bin/sh /usr/share/wildfly/bin/launch.sh standalone standalone.xml 0.0.0.0
           ├─26509 /bin/sh /usr/share/wildfly/bin/standalone.sh -c standalone.xml -b 0.0.0.0
           └─26579 java -agentpath:/usr/lib64/libabrt-java-connector.so=abrt=on -D[Standalone] -server -XX:+UseCompressedOops -Xms64m -Xmx512m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Djboss.module...

Feb 11 14:19:10 msrb-laptop systemd[1]: Started The WildFly Application Server.


# systemctl stop wildfly
# systemctl status wildfly
wildfly.service - The WildFly Application Server
   Loaded: loaded (/usr/lib/systemd/system/wildfly.service; disabled)
   Active: inactive (dead)

Feb 11 14:19:10 msrb-laptop systemd[1]: Starting The WildFly Application Server...
Feb 11 14:19:10 msrb-laptop systemd[1]: Started The WildFly Application Server.
Feb 11 14:24:47 msrb-laptop systemd[1]: Stopping The WildFly Application Server...
Feb 11 14:24:47 msrb-laptop systemd[1]: Stopped The WildFly Application Server.

$ ps aux |grep launch.sh
msrb     27328  0.0  0.0 112664   984 pts/6    S+   14:27   0:00 grep --color=auto launch.sh

Only exception in my server.log is:
Caused by: java.net.UnknownHostException: msrb-laptop
        at java.net.Inet4AddressImpl.lookupAllHostAddr(Native Method) [rt.jar:1.7.0_51]
        at java.net.InetAddress$1.lookupAllHostAddr(InetAddress.java:901) [rt.jar:1.7.0_51]
        at java.net.InetAddress.getAddressesFromNameService(InetAddress.java:1293) [rt.jar:1.7.0_51]
        at java.net.InetAddress.getLocalHost(InetAddress.java:1469) [rt.jar:1.7.0_51]
        ... 14 more

But it's not really a problem.

Comment 4 Juraci Paixão Kröhling 2014-02-11 16:03:53 UTC
Strange, it happened to two VMs, on two different hosts: one that I use for hosting my application, and one on my development machine. As I imagine that you've tested on a 64bits VM, I've then booted a new 64bits VM (I tested with x86 before), and it happened again. 

I've used a clean VM, created by using the following command and performing a minimal install:

# virt-install --ram 1024 -l http://mirror.kroehling.de/pub/fedora/linux/releases/20/Fedora/x86_64/os/ --os-type=linux --os-variant=fedora20 --disk path=/usr/local/data/projects/virtual-images/wildfly64.qcow2,format=qcow2 --vnc --name wildfly64

As requested, here's the "rpm -V wildfly" (from the 64bits VM):
[root@localhost standalone]# rpm -V wildfly
S.5....T.  c /etc/wildfly/standalone/logging.properties

Logs:

2014-02-11 15:58:11,293 DEBUG [org.jboss.as.config] (MSC service thread 1-2) VM Arguments: -D[Standalone] -XX:+UseCompressedOops -Xms64m -Xmx512m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true -Dorg.jboss.boot.log.file=/usr/share/wildfly/standalone/log/server.log -Dlogging.configuration=file:/usr/share/wildfly/standalone/configuration/logging.properties 
2014-02-11 15:58:12,958 INFO  [org.xnio] (MSC service thread 1-2) XNIO version 3.2.0.Beta3
2014-02-11 15:58:12,970 INFO  [org.jboss.as.server] (Controller Boot Thread) JBAS015888: Creating http management service using socket-binding (management-http)
2014-02-11 15:58:12,982 INFO  [org.xnio.nio] (MSC service thread 1-2) XNIO NIO Implementation Version 3.2.0.Beta3
2014-02-11 15:58:13,040 INFO  [org.jboss.remoting] (MSC service thread 1-2) JBoss Remoting version 4.0.0.Beta1
2014-02-11 15:58:13,106 INFO  [org.jboss.as.clustering.infinispan] (ServerService Thread Pool -- 33) JBAS010280: Activating Infinispan subsystem.
2014-02-11 15:58:13,188 INFO  [org.jboss.as.connector.subsystems.datasources] (ServerService Thread Pool -- 28) JBAS010403: Deploying JDBC-compliant driver class org.h2.Driver (version 1.3)
2014-02-11 15:58:13,191 INFO  [org.jboss.as.jsf] (ServerService Thread Pool -- 39) JBAS012615: Activated the following JSF Implementations: [main]
2014-02-11 15:58:13,185 INFO  [org.jboss.as.naming] (ServerService Thread Pool -- 41) JBAS011800: Activating Naming Subsystem
2014-02-11 15:58:13,255 INFO  [org.jboss.as.security] (ServerService Thread Pool -- 46) JBAS013171: Activating Security Subsystem
2014-02-11 15:58:13,378 INFO  [org.jboss.as.webservices] (ServerService Thread Pool -- 50) JBAS015537: Activating WebServices Extension
2014-02-11 15:58:13,442 INFO  [org.jboss.as.connector.logging] (MSC service thread 1-2) JBAS010408: Starting JCA Subsystem (IronJacamar 1.1.2.Final)
2014-02-11 15:58:13,495 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 49) JBAS017502: Undertow 1.0.0.Beta30 starting
2014-02-11 15:58:13,568 INFO  [org.jboss.as.security] (MSC service thread 1-2) JBAS013170: Current PicketBox version=4.0.18.Final
2014-02-11 15:58:13,577 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-1) JBAS017502: Undertow 1.0.0.Beta30 starting
2014-02-11 15:58:13,629 INFO  [org.jboss.as.connector.deployers.jdbc] (MSC service thread 1-2) JBAS010417: Started Driver service with driver-name = h2
2014-02-11 15:58:13,704 INFO  [org.jboss.as.naming] (MSC service thread 1-2) JBAS011802: Starting Naming Service
2014-02-11 15:58:13,751 INFO  [org.jboss.as.mail.extension] (MSC service thread 1-1) JBAS015400: Bound mail session [java:jboss/mail/Default]
2014-02-11 15:58:13,868 INFO  [org.wildfly.extension.undertow] (ServerService Thread Pool -- 49) JBAS017527: Creating file handler for path /usr/share/wildfly/welcome-content
2014-02-11 15:58:14,153 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) JBAS017525: Started server default-server.
2014-02-11 15:58:14,156 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) JBAS017531: Host default-host starting
2014-02-11 15:58:14,179 WARN  [org.jboss.as.webservices] (ServerService Thread Pool -- 50) JBAS015506: Cannot load WS deployment aspects from /META-INF/stack-specific-deployment-aspects.xml
2014-02-11 15:58:14,393 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) JBAS017519: Undertow HTTP listener default listening on /0.0.0.0:8080
2014-02-11 15:58:14,548 INFO  [org.jboss.ws.common.management] (MSC service thread 1-2) JBWS022052: Starting JBoss Web Services - Stack CXF Server 4.2.0.Final
2014-02-11 15:58:15,018 ERROR [org.jboss.as.domain.http.api.undertow] (MSC service thread 1-1) JBAS015102: Unable to load console module for slot main, disabling console
2014-02-11 15:58:15,047 INFO  [org.jboss.as.remoting] (MSC service thread 1-2) JBAS017100: Listening on 127.0.0.1:9999
2014-02-11 15:58:15,085 INFO  [org.jboss.as.server.deployment.scanner] (MSC service thread 1-2) JBAS015012: Started FileSystemDeploymentService for directory /usr/share/wildfly/standalone/deployments
2014-02-11 15:58:15,086 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-2) JBAS010400: Bound data source [java:jboss/datasources/ExampleDS]
2014-02-11 15:58:15,401 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015961: Http management interface listening on http://127.0.0.1:9990/management
2014-02-11 15:58:15,402 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015951: Admin console listening on http://127.0.0.1:9990
2014-02-11 15:58:15,402 INFO  [org.jboss.as] (Controller Boot Thread) JBAS015874: WildFly 8.0.0.CR1 "WildFly" started in 5722ms - Started 184 of 232 services (78 services are lazy, passive or on-demand)
2014-02-11 15:58:19,653 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-1) JBAS017532: Host default-host stopping
2014-02-11 15:58:19,653 INFO  [org.jboss.as.connector.subsystems.datasources] (MSC service thread 1-1) JBAS010409: Unbound data source [java:jboss/datasources/ExampleDS]
2014-02-11 15:58:19,660 ERROR [stderr] (ServerService Thread Pool -- 1) Exception in thread "ServerService Thread Pool -- 1" java.lang.IllegalStateException: Illegal controller state
2014-02-11 15:58:19,661 ERROR [stderr] (ServerService Thread Pool -- 1)         at org.jboss.msc.service.ServiceControllerImpl$StopContextImpl.complete(ServiceControllerImpl.java:2436)
2014-02-11 15:58:19,662 ERROR [stderr] (ServerService Thread Pool -- 1)         at org.jboss.as.ejb3.remote.EJBTransactionRecoveryService$1.run(EJBTransactionRecoveryService.java:91)
2014-02-11 15:58:19,662 ERROR [stderr] (ServerService Thread Pool -- 1)         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
2014-02-11 15:58:19,662 ERROR [stderr] (ServerService Thread Pool -- 1)         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
2014-02-11 15:58:19,662 ERROR [stderr] (ServerService Thread Pool -- 1)         at java.lang.Thread.run(Thread.java:744)
2014-02-11 15:58:19,663 ERROR [stderr] (ServerService Thread Pool -- 1)         at org.jboss.threads.JBossThread.run(JBossThread.java:122)
2014-02-11 15:58:19,670 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) JBAS017521: Undertow HTTP listener default suspending
2014-02-11 15:58:19,671 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-2) JBAS017520: Undertow HTTP listener default stopped, was bound to /0.0.0.0:8080
2014-02-11 15:58:19,671 ERROR [stderr] (ServerService Thread Pool -- 52) Exception in thread "ServerService Thread Pool -- 52" java.lang.IllegalStateException: Illegal controller state
2014-02-11 15:58:19,672 ERROR [stderr] (ServerService Thread Pool -- 52)        at org.jboss.msc.service.ServiceControllerImpl$StopContextImpl.complete(ServiceControllerImpl.java:2436)
2014-02-11 15:58:19,672 ERROR [stderr] (ServerService Thread Pool -- 52)        at org.jboss.as.connector.subsystems.datasources.AbstractDataSourceService$1.run(AbstractDataSourceService.java:145)
2014-02-11 15:58:19,672 ERROR [stderr] (ServerService Thread Pool -- 52)        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
2014-02-11 15:58:19,672 ERROR [stderr] (ServerService Thread Pool -- 52)        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
2014-02-11 15:58:19,673 ERROR [stderr] (ServerService Thread Pool -- 52)        at java.lang.Thread.run(Thread.java:744)
2014-02-11 15:58:19,673 ERROR [stderr] (ServerService Thread Pool -- 52)        at org.jboss.threads.JBossThread.run(JBossThread.java:122)
2014-02-11 15:58:19,674 INFO  [org.wildfly.extension.undertow] (MSC service thread 1-1) JBAS017506: Undertow 1.0.0.Beta30 stopping


And the process:

[root@localhost standalone]# ps auxwww | grep wildf
wildfly   1470  0.0  0.1 113116  1480 ?        S    15:58   0:00 /bin/sh /usr/share/wildfly/bin/standalone.sh -c standalone.xml -b 0.0.0.0
wildfly   1536  2.0 13.7 1597896 140180 ?      Sl   15:58   0:05 java -D[Standalone] -server -XX:+UseCompressedOops -Xms64m -Xmx512m -XX:MaxPermSize=256m -Djava.net.preferIPv4Stack=true -Djboss.modules.system.pkgs=org.jboss.byteman -Djava.awt.headless=true -Dorg.jboss.boot.log.file=/usr/share/wildfly/standalone/log/server.log -Dlogging.configuration=file:/usr/share/wildfly/standalone/configuration/logging.properties -jar /usr/share/wildfly/jboss-modules.jar -mp /usr/share/wildfly/modules org.jboss.as.standalone -Djboss.home.dir=/usr/share/wildfly -Djboss.server.base.dir=/usr/share/wildfly/standalone -c standalone.xml -b 0.0.0.0

SystemD:

[root@localhost standalone]# systemctl status wildfly
wildfly.service - The WildFly Application Server
   Loaded: loaded (/usr/lib/systemd/system/wildfly.service; disabled)
   Active: inactive (dead)

Feb 11 15:58:08 localhost.localdomain systemd[1]: Starting The WildFly Application Server...
Feb 11 15:58:08 localhost.localdomain systemd[1]: Started The WildFly Application Server.
Feb 11 15:58:19 localhost.localdomain systemd[1]: Stopping The WildFly Application Server...
Feb 11 15:58:19 localhost.localdomain systemd[1]: Stopped The WildFly Application Server.

Comment 5 Marek Goldmann 2014-02-13 09:19:00 UTC
I guess there may be some subtle change introduced in the dependency tree of WildFly CR1 that wasn't catch. With the WildFly 8.0.0.Final release I'm not going to look into it before I upgrade to Final. I'm starting the package upgrade process immediately.


Note You need to log in before you can comment on or make changes to this bug.