WEBLOGIC ADMIN SERVER FAILING TO START WITH ERROR: SERVICE WEBLOGIC.SERVER.SERVERLIFECYCLESERVICE WAS STARTED AT LEVEL 9 BUT IT HAS A RUN LEVEL OF 10

We had an issue with shared storage server which is used to store weblogic admin server configuration. So, we restarted the admin server once the storage issue was resolved. But restart failed with below errors:

<Nov 13, 2022 10:06:15,079 PM PST> <Critical> <WebLogicServer> <BEA-000386> <Server subsystem failed. Reason: A MultiException has 20 exceptions.  They are:

1. java.lang.NullPointerException
2. java.lang.IllegalStateException: Unable to perform operation: post construct on weblogic.store.admin.DefaultStoreService
3. java.lang.IllegalArgumentException: While attempting to resolve the dependencies of weblogic.transaction.internal.TransactionService errors were found
4. java.lang.IllegalStateException: Unable to perform operation: resolve on weblogic.transaction.internal.TransactionService
5. java.lang.IllegalArgumentException: While attempting to resolve the dependencies of weblogic.jdbc.common.internal.JDBCService errors were found
20. java.lang.IllegalStateException: Unable to perform operation: resolve on weblogic.application.services.ApplicationShutdownService

        at org.jvnet.hk2.internal.Collector.throwIfErrors(Collector.java:89)
        at org.jvnet.hk2.internal.ClazzCreator.resolveAllDependencies(ClazzCreator.java:250)
        at org.jvnet.hk2.internal.ClazzCreator.create(ClazzCreator.java:358)
        at org.jvnet.hk2.internal.SystemDescriptor.create(SystemDescriptor.java:487)
        at org.glassfish.hk2.runlevel.internal.AsyncRunLevelContext.findOrCreate(AsyncRunLevelContext.java:305)
        Truncated. see log file for complete stacktrace
Caused By: java.lang.NullPointerException

<Nov 13, 2022 10:06:15,084 PM PST> <Notice> <WebLogicServer> <BEA-000365> <Server state changed to FAILED.>
<Nov 13, 2022 10:06:15,084 PM PST> <Error> <WebLogicServer> <BEA-000383> <A critical service failed. The server will shut itself down.>
<Nov 13, 2022 10:06:15,085 PM PST> <Error> <Kernel> <BEA-000802> <ExecuteRequest failed
 A MultiException has 1 exceptions.  They are:
1. java.lang.IllegalStateException: Service weblogic.server.ServerLifeCycleService was started at level 9 but it has a run level of 10.  The full descriptor is SystemDescriptor(
        implementation=weblogic.server.ServerLifeCycleService
        name=ServerLifeCycleService
        contracts={weblogic.server.ServerLifeCycleService,weblogic.server.ServerService}
        scope=org.glassfish.hk2.runlevel.RunLevel
        qualifiers={javax.inject.Named}
        descriptorType=CLASS
        descriptorVisibility=NORMAL
        metadata=runLevelValue={10}
        rank=0
        loader=HK2LoaderImpl(weblogic.utils.classloaders.GenericClassLoader@306f16f3 finder: weblogic.utils.classloaders.CodeGenClassFinder@2208ac0a annotation: )
        proxiable=null
        proxyForSameScope=null
        analysisName=null
        id=159
        locatorId=0
        identityHashCode=813384228
        reified=true)

It was not very clear what was causing issue from the above logs. So, started admin server using strace command to check if admin server process was waiting on any file. Following is the snippet from the output:

99291 22:15:04 open("/oracle/config/aserver/domains/soa_domain/servers/AdminServer/data/store/default/_WLS_ADMINSERVER000000.DAT", O_RDWR|O_CREAT|O_DSYNC|O_DIRECT, 0600) = 976 <0.000443>
99291 22:15:04 fcntl(976, F_SETLK, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=0, l_len=1}) = -1 EAGAIN (Resource temporarily unavailable) <0.000023>
99291 22:15:04 close(976) = 0 <0.000035>

So, admin server was trying to read _WLS_ADMINSERVER000000.DAT and failing with “Resource temporarily unavailable “. After googling found that one of reason for this error could be due to failing to acquire file lock. So, checked if there were any locks on the file using lslocks command:

$ lslocks
COMMAND            PID  TYPE SIZE MODE  M      START        END PATH
liagent         109885 POSIX   0B WRITE 0 1073741824 1073742335 /var
master            1562 FLOCK   0B WRITE 0          0          0 /var
master            1562 FLOCK   0B WRITE 0          0          0 /var
java             11926 POSIX   0B WRITE 0          0          0 /oracle/config/aserver
java             11926 POSIX   0B WRITE 0          0          0 /oracle/config/aserver
java            100870 POSIX   1M WRITE 0          0          0 /oracle/config/aserver/domains/soa_domain/servers/AdminServer/data/store/default/_WLS_ADMINSERVER000000.DAT

So, assumed that lock acquired by previous admin server process was not released properly due to storage issue. To resolve issue quickly, we removed _WLS_ADMINSERVER000000.DAT file and started admin server. Admin server came up this time. Felt satisfied for resolving issue but it didn’t last long. After sometime, we received a ticket saying that em console was not responding. Thread dump showed 260 occurrences of the following thread:

"[STUCK] ExecuteThread: '11' for queue: 'weblogic.kernel.Default (self-tuning)'" prio=10 id=96
   java.lang.Thread.State: BLOCKED (on object monitor)
        - waiting on <0x72285649> (a weblogic.logging.FileStreamHandler)
        at com.bea.logging.RotatingFileStreamHandler.publish(RotatingFileStreamHandler.java:81)
        at java.util.logging.Logger.log(Logger.java:738)
        at com.bea.logging.BaseLogger.log(BaseLogger.java:66)
        at weblogic.logging.WLLogger.log(WLLogger.java:35)
        at weblogic.management.logging.DomainLogHandlerImpl.publishLogEntries(DomainLogHandlerImpl.java:137)
        at weblogic.management.logging.DomainLogHandlerImpl_WLSkel.invoke(Unknown Source)
        at weblogic.rmi.internal.BasicServerRef.invoke(BasicServerRef.java:646)
        at weblogic.rmi.internal.BasicServerRef$2.run(BasicServerRef.java:534)
        at weblogic.security.acl.internal.AuthenticatedSubject.doAs(AuthenticatedSubject.java:386)
        at weblogic.security.service.SecurityManager.runAs(SecurityManager.java:163)
        at weblogic.rmi.internal.BasicServerRef.handleRequest(BasicServerRef.java:531)
        at weblogic.rmi.internal.wls.WLSExecuteRequest.run(WLSExecuteRequest.java:138)
        at weblogic.invocation.ComponentInvocationContextManager._runAs(ComponentInvocationContextManager.java:352)
        at weblogic.invocation.ComponentInvocationContextManager.runAs(ComponentInvocationContextManager.java:337)
        at weblogic.work.LivePartitionUtility.doRunWorkUnderContext(LivePartitionUtility.java:57)
        at weblogic.work.PartitionUtility.runWorkUnderContext(PartitionUtility.java:41)
        at weblogic.work.SelfTuningWorkManagerImpl.runWorkUnderContext(SelfTuningWorkManagerImpl.java:652)
        at weblogic.work.ExecuteThread.execute(ExecuteThread.java:420)
        at weblogic.work.ExecuteThread.run(ExecuteThread.java:360)

Lock that these threads were waiting on was owned by following thread:

"[ACTIVE] ExecuteThread: '12' for queue: 'weblogic.kernel.Default (self-tuning)'" prio=10 id=97
   java.lang.Thread.State: RUNNABLE
        at java.io.FileOutputStream.writeBytes(Native Method)
        at java.io.FileOutputStream.write(FileOutputStream.java:326)
        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
        - locked <0x4e8e4aa0> (a java.io.BufferedOutputStream)
        at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
        - locked <0x72285649> (a weblogic.logging.FileStreamHandler)
        at com.bea.logging.RotatingFileOutputStream.flush(RotatingFileOutputStream.java:256)
        at sun.nio.cs.StreamEncoder.implFlush(StreamEncoder.java:297)
        - locked <0x2feef7a5> (a java.io.OutputStreamWriter)
        at sun.nio.cs.StreamEncoder.flush(StreamEncoder.java:141)
        at java.io.OutputStreamWriter.flush(OutputStreamWriter.java:229)
        - locked <0x72285649> (a weblogic.logging.FileStreamHandler)
        at java.util.logging.StreamHandler.flush(StreamHandler.java:259)
        - locked <0x72285649> (a weblogic.logging.FileStreamHandler)
        at com.bea.logging.RotatingFileStreamHandler.publish(RotatingFileStreamHandler.java:88)
        at java.util.logging.Logger.log(Logger.java:738)
        at com.bea.logging.BaseLogger.log(BaseLogger.java:66)
        at weblogic.logging.WLLogger.log(WLLogger.java:35)
        at weblogic.management.logging.DomainLogHandlerImpl.publishLogEntries(DomainLogHandlerImpl.java:137)
        at weblogic.logging.DomainLogBroadcasterClient$2.run(DomainLogBroadcasterClient.java:233)
        at weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:678)
        at weblogic.invocation.ComponentInvocationContextManager._runAs(ComponentInvocationContextManager.java:352)
        at weblogic.invocation.ComponentInvocationContextManager.runAs(ComponentInvocationContextManager.java:337)
        at weblogic.work.LivePartitionUtility.doRunWorkUnderContext(LivePartitionUtility.java:57)
        at weblogic.work.PartitionUtility.runWorkUnderContext(PartitionUtility.java:41)
        at weblogic.work.SelfTuningWorkManagerImpl.runWorkUnderContext(SelfTuningWorkManagerImpl.java:652)
        at weblogic.work.ExecuteThread.execute(ExecuteThread.java:420)
        at weblogic.work.ExecuteThread.run(ExecuteThread.java:360)

Looked like this thread was stuck while writing logs to file and meanwhile, weblogic spun 260 threads to rotate log file. As first thread was not progress and not releasing the lock, all other threads were stuck too. We suspected that this issue could be related to storage. lslocks output confirmed that previous process still holding some locks in shared mount. Also, top command showed zombie processes. To clear off these locks we rebooted VM and issue finally got resolved.

Comments

Post a Comment

Popular posts from this blog

HOW WE REDUCED SOA OSB PROVISIONING FROM 4 DAYS TO 4 HOURS

 In our organization, we’ve undertaken the task of upgrading both SOA and OSB from version 12.2.1.3 to 12.2.1.4. This involves an out-of-place migration approach, wherein we create a new environment and switch traffic during the cutover. As you know, this process typically requires several days we opt for manual provisioing. A very significant amount of automation work was previously accomplished for 12.2.1.3 by our predecessors. Despite these efforts, the process still used to take lot of time due to following factors: Bugs in existing automation. For example, SOA composite deployments is not stable which warrants lot of manual work Import of 10s of TLS Certificates into KSS Manual retiring and shutting down of services Monitoring setup Miscellaneous: Increasing Log file count, enabling GC logging, changing heap parameters, bash profile changes While our current automation initiatives have yielded substantial savings, we aimed to capitalize on this upgrade activity to enable end-t...
Read more

NOT ABLE TO START RABBITMQ CLUSTER: CANNOT DECLARE A QUEUE ‘~S’ ON NODE ‘~S’: ~255P

We have 7 node rabbitmq cluster and we are using sharding queues. We have shutdown all non prod rabbitmq nodes as part of VM patching. As it was non prod, we thought of shutting down all together instead of rolling patching. We couldn’t start the any of the rabbitmq post patching. All of nodes were failing to start with the below error: 2022-06-23 05:13:10.104845-07:00 [error] <0.647.0> “Cannot declare a queue ‘~s’ on node ‘~s’: ~255p”, 2022-06-23 05:13:10.104845-07:00 [error] <0.647.0> [“queue ‘sharding: shard.my.queue – rabbit@rabbit1’ in vhost ‘my_vhost'” This is a known issue in some old versions of rabbitmq. rabbitmq node fails to come up with above error. Work around for this is to disable sharding policy for the problematic sharding queue. It can be done either from command line or from rabbitmq admin page. It requires to connect a running node. But as all the nodes were down, we could not disable sharding policy. Luckily, rabbitmq allows disabling sharding pulgi...
Read more

SOA SUITE 12.2.1.4 INSTALLATION: GOT EXCEPTION WHEN AUTO CONFIGURING THE SCHEMA COMPONENT(S) WITH DATA OBTAINED FROM SHADOW TABLE

  We planned to do out of place upgrade from soa suite 12.2.1.3 to 12.2.1.4. As part of this, we planned to automate end to end provisioning. While executing domain configuration using ansible and python scripts, we got following error in domain creation step. Got exception when auto configuring the schema component(s) with data obtained from shadow table. Failed to build JDBC Connection object: com.oracle.cie.domain.script.jython.CommandExceptionHandler. exception. Quick internet search gave few solutions like deleting domain-registry.xml file, verifying dehydration store password supplied to script etc. But none of them helped. After trying several options, I thought I might have done some stupid error prior to domain creation step. To track down the issue, though of checking what getDatabaseDefaults actually doing. I tried to grep for the getDatabaseDefaults function call inside oracle home. But couldn’t find the source code for the python function. As a final resort, thought of...
Read more