Bug 1536048

Summary: Unknown Java Time Zone Prevents RHV From Starting.
Product: Red Hat Enterprise Linux 7 Reporter: Bernie Hoefer <bhoefer>
Component: java-1.8.0-openjdkAssignee: Andrew John Hughes <ahughes>
Status: CLOSED NOTABUG QA Contact: zzambers
Severity: medium Docs Contact:
Priority: unspecified    
Version: 7.4CC: ahughes, bhoefer, dbhole, jvanek, zzambers
Target Milestone: rc   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-02-08 14:18:04 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Bernie Hoefer 2018-01-18 14:32:57 UTC
Description of problem:

1st, some background:  I live in the the Eastern U.S.A. time zone and prefer my servers to not observe Daylight Saving Time.  So when I build a server, I execute this command so that they show an offset of -0500 from UTC all year long:

  rm -f /etc/localtime; ln -s /usr/share/zoneinfo/EST /etc/localtime

I installed a new Red Hat Virtualization (RHV) Manager machine, but the ovirt-engine.service would kill itself whenever I tried to start it.  These are the messages I saw in /var/log/messages:

  ovirt-engine.py[17503]: 2018-01-18 01:42:19,233-0500 ovirt-engine: ERROR run:554 Error: process terminated with status code 1

  systemd[1]: ovirt-engine.service: main process exited, code=exited, status=1/FAILURE

Looking in the /var/log/ovirt-engine/boot.log, I found the following error:

  ERROR [org.jboss.msc.service.fail] MSC000001: Failed to start service jboss.as.server-controller: org.jboss.msc.service.StartException in service jboss.as.server-controller: Failed to start service
  {...}
  Caused by: java.time.zone.ZoneRulesException: Unknown time-zone ID: EST
    at java.time.zone.ZoneRulesProvider.getProvider(ZoneRulesProvider.java:272) [rt.jar:1.8.0_161]
    at java.time.zone.ZoneRulesProvider.getRules(ZoneRulesProvider.java:227) [rt.jar:1.8.0_161]
    at java.time.ZoneRegion.ofId(ZoneRegion.java:120) [rt.jar:1.8.0_161]
    at java.time.ZoneId.of(ZoneId.java:411) [rt.jar:1.8.0_161]
    at java.time.ZoneId.of(ZoneId.java:359) [rt.jar:1.8.0_161]

When I changed my machine's time zone to Eastern *with* Daylight Saving Time via this method:

  rm -f /etc/localtime; ln -s /usr/share/zoneinfo/EST5EDT /etc/localtime

...ovirt-engine.service worked fine.

This is a new problem, as just in September 2017 I built a RHV Manager machine using EST and it worked fine.



Version-Release number of selected component (if applicable):

java-1.8.0-openjdk-1.8.0.161-0.b14.el7_4.x86_64


How reproducible:

I suspect this is reproducible on any application server (Tomcat, JBoss EAP, etc.) that uses OpenJDK, but am not sure.  I encountered this with RHV's Manager's ovirt-engine's JBoss EAP 7.1.0.GA and will thus give the reproduction steps for it.

Steps to Reproduce:

1. Change time zone via:
   rm -f /etc/localtime; ln -s /usr/share/zoneinfo/EST /etc/localtime

2. Start the ovirt-engine service via:
   systemctl start ovirt-engine.service



Actual results:

The ovirt-engine service does not start; one sees a "java.time.zone.ZoneRulesException: Unknown time-zone ID: EST" error in /var/log/ovirt-engine/boot.log.



Expected results:

The ovirt-engine starts with no problem.

Comment 2 zzambers 2018-03-23 14:24:39 UTC
I looked at this one a little and I was able to reproduce identical stack trace (icluding line numbers), just by calling:

ZoneId.of("EST");

Exception in thread "main" java.time.zone.ZoneRulesException: Unknown time-zone ID: EST
	at java.time.zone.ZoneRulesProvider.getProvider(ZoneRulesProvider.java:272)
	at java.time.zone.ZoneRulesProvider.getRules(ZoneRulesProvider.java:227)
	at java.time.ZoneRegion.ofId(ZoneRegion.java:120)
	at java.time.ZoneId.of(ZoneId.java:411)
	at java.time.ZoneId.of(ZoneId.java:359)
	at ZoneIdTest.main(ZoneIdTest.java:24)


However I am not sure this one is actually bug in JDK, since javadoc description of SHORT_IDS field [1] in the ZoneId class says that use of short zone ids have been deprecated. And looks to me, that correct way to use these deprecated SHORT_IDS (such as EST) is by using second form of Zoneid.of method:

ZoneId.of("EST", ZoneId.SHORT_IDS);

which works, and it is also the form, which is used internally by JDK in Timezone class by toZoneId method [2]. ( I expect, that rest of the stack trace is outside of JDK, when not included. )

Nevertheless adding qa_ack.

[1] https://docs.oracle.com/javase/8/docs/api/java/time/ZoneId.html#SHORT_IDS
[2] http://hg.openjdk.java.net/jdk8u/jdk8u/jdk/file/f940e7a48b72/src/share/classes/java/util/TimeZone.java#l539

Comment 3 Andrew John Hughes 2018-03-23 21:57:17 UTC
(In reply to zzambers from comment #2)
> I looked at this one a little and I was able to reproduce identical stack
> trace (icluding line numbers), just by calling:
> 
> ZoneId.of("EST");

I suspected this might be the case when I saw the initial stack trace, but just haven't had time to try it. Thanks for confirming.

> 
> Exception in thread "main" java.time.zone.ZoneRulesException: Unknown
> time-zone ID: EST
> 	at java.time.zone.ZoneRulesProvider.getProvider(ZoneRulesProvider.java:272)
> 	at java.time.zone.ZoneRulesProvider.getRules(ZoneRulesProvider.java:227)
> 	at java.time.ZoneRegion.ofId(ZoneRegion.java:120)
> 	at java.time.ZoneId.of(ZoneId.java:411)
> 	at java.time.ZoneId.of(ZoneId.java:359)
> 	at ZoneIdTest.main(ZoneIdTest.java:24)
> 
> 
> However I am not sure this one is actually bug in JDK, since javadoc
> description of SHORT_IDS field [1] in the ZoneId class says that use of
> short zone ids have been deprecated. And looks to me, that correct way to
> use these deprecated SHORT_IDS (such as EST) is by using second form of
> Zoneid.of method:
> 
> ZoneId.of("EST", ZoneId.SHORT_IDS);
> 
> which works, and it is also the form, which is used internally by JDK in
> Timezone class by toZoneId method [2]. ( I expect, that rest of the stack
> trace is outside of JDK, when not included. )

The interesting bit about [2] is just above that call:

   public ZoneId toZoneId() {

        String id = getID();

        if (ZoneInfoFile.useOldMapping() && id.length() == 3) {

            if ("EST".equals(id))

                return ZoneId.of("America/New_York");

It could be that useOldMapping has changed value. I'll check this out.

But we really need to know the rest of that stack trace to be sure.

> 
> Nevertheless adding qa_ack.
> 
> [1] https://docs.oracle.com/javase/8/docs/api/java/time/ZoneId.html#SHORT_IDS
> [2]
> http://hg.openjdk.java.net/jdk8u/jdk8u/jdk/file/f940e7a48b72/src/share/
> classes/java/util/TimeZone.java#l539

Comment 4 Bernie Hoefer 2018-04-09 22:05:28 UTC
(In reply to Andrew John Hughes from comment #3)
===
> But we really need to know the rest of that stack trace to be sure.
===

Sorry, I'm not familiar with how to get a Java stack trace.  Are the lines from /var/log/ovirt-engine/boot.log and /var/log/message, far below, what you want?


# ll /etc/localtime 
lrwxrwxrwx. 1 root root 27 Jan 18 01:44 /etc/localtime -> /usr/share/zoneinfo/EST5EDT

# rm -f /etc/localtime; ln -s /usr/share/zoneinfo/EST /etc/localtime

# ll /etc/localtime 
lrwxrwxrwx. 1 root root 23 Apr  9 16:52 /etc/localtime -> /usr/share/zoneinfo/EST

# systemctl status ovirt-engine.service
● ovirt-engine.service - oVirt Engine
   Loaded: loaded (/usr/lib/systemd/system/ovirt-engine.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2018-03-09 16:39:59 EST; 1 months 0 days ago
 Main PID: 1697 (ovirt-engine.py)
   CGroup: /system.slice/ovirt-engine.service
           ├─1697 /usr/bin/python /usr/share/ovirt-engine/services/ovirt-engi...
           └─3109 ovirt-engine -server -XX:+TieredCompilation -Xms1024M -Xmx1...
Mar 09 16:39:55 controller1.localdomain systemd[1]: Starting oVirt Engine...
Mar 09 16:39:56 controller1.localdomain ovirt-engine.py[1697]: 2018-03-09 16:39:5...
Mar 09 16:39:59 controller1.localdomain ovirt-engine.py[1697]: 2018-03-09 16:39:5...
Mar 09 16:39:59 controller1.localdomain systemd[1]: Started oVirt Engine.
Hint: Some lines were ellipsized, use -l to show in full.

# systemctl restart ovirt-engine.service

# systemctl status ovirt-engine.service
● ovirt-engine.service - oVirt Engine
   Loaded: loaded (/usr/lib/systemd/system/ovirt-engine.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Mon 2018-04-09 16:53:27 EST; 721ms ago
  Process: 12454 ExecStart=/usr/share/ovirt-engine/services/ovirt-engine/ovirt-engine.py --redirect-output --systemd=notify $EXTRA_ARGS start (code=exited, status=1/FAILURE)
 Main PID: 12454 (code=exited, status=1/FAILURE)
Apr 09 16:53:22 controller1.localdomain systemd[1]: Starting oVirt Engine...
Apr 09 16:53:22 controller1.localdomain ovirt-engine.py[12454]: 2018-04-09 16:53:...
Apr 09 16:53:24 controller1.localdomain ovirt-engine.py[12454]: 2018-04-09 16:53:...
Apr 09 16:53:24 controller1.localdomain systemd[1]: Started oVirt Engine.
Apr 09 16:53:27 controller1.localdomain ovirt-engine.py[12454]: 2018-04-09 16:53:...
Apr 09 16:53:27 controller1.localdomain systemd[1]: ovirt-engine.service: main p...E
Apr 09 16:53:27 controller1.localdomain systemd[1]: Unit ovirt-engine.service en....
Apr 09 16:53:27 controller1.localdomain systemd[1]: ovirt-engine.service failed.
Hint: Some lines were ellipsized, use -l to show in full.

# cat /var/log/ovirt-engine/boot.log 
16:53:25,619 INFO  [org.jboss.modules] JBoss Modules version 1.6.0.Final-redhat-1
16:53:26,333 INFO  [org.jboss.msc] JBoss MSC version 1.2.7.SP1-redhat-1
16:53:26,873 INFO  [org.jboss.as] WFLYSRV0049: JBoss EAP 7.1.0.GA (WildFly Core 3.0.10.Final-redhat-1) starting
16:53:27,390 ERROR [org.jboss.msc.service.fail] MSC000001: Failed to start service jboss.as.server-controller: org.jboss.msc.service.StartException in service jboss.as.server-controller: Failed to start service
	at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1978) [jboss-msc.jar:1.2.7.SP1-redhat-1]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [rt.jar:1.8.0_161]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [rt.jar:1.8.0_161]
	at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_161]
Caused by: java.lang.ExceptionInInitializerError
	at org.jboss.as.controller.services.path.PathInfoHandler$Builder.build(PathInfoHandler.java:331)
	at org.jboss.as.server.ServerEnvironmentResourceDescription.registerOperations(ServerEnvironmentResourceDescription.java:124) [wildfly-server-3.0.10.Final-redhat-1.jar:3.0.10.Final-redhat-1]
	at org.jboss.as.controller.registry.NodeSubregistry.registerChild(NodeSubregistry.java:109)
	at org.jboss.as.controller.registry.ConcreteResourceRegistration.registerSubModel(ConcreteResourceRegistration.java:231)
	at org.jboss.as.server.controller.resources.ServerRootResourceDefinition.registerOperations(ServerRootResourceDefinition.java:355) [wildfly-server-3.0.10.Final-redhat-1.jar:3.0.10.Final-redhat-1]
	at org.jboss.as.controller.DelegatingResourceDefinition.registerOperations(DelegatingResourceDefinition.java:41)
	at org.jboss.as.controller.registry.ManagementResourceRegistration$Factory.createRegistration(ManagementResourceRegistration.java:426)
	at org.jboss.as.controller.AbstractControllerService.start(AbstractControllerService.java:330)
	at org.jboss.as.server.ServerService.start(ServerService.java:296) [wildfly-server-3.0.10.Final-redhat-1.jar:3.0.10.Final-redhat-1]
	at org.jboss.msc.service.ServiceControllerImpl$StartTask.startService(ServiceControllerImpl.java:2032) [jboss-msc.jar:1.2.7.SP1-redhat-1]
	at org.jboss.msc.service.ServiceControllerImpl$StartTask.run(ServiceControllerImpl.java:1955) [jboss-msc.jar:1.2.7.SP1-redhat-1]
	... 3 more
Caused by: java.time.zone.ZoneRulesException: Unknown time-zone ID: EST
	at java.time.zone.ZoneRulesProvider.getProvider(ZoneRulesProvider.java:272) [rt.jar:1.8.0_161]
	at java.time.zone.ZoneRulesProvider.getRules(ZoneRulesProvider.java:227) [rt.jar:1.8.0_161]
	at java.time.ZoneRegion.ofId(ZoneRegion.java:120) [rt.jar:1.8.0_161]
	at java.time.ZoneId.of(ZoneId.java:411) [rt.jar:1.8.0_161]
	at java.time.ZoneId.of(ZoneId.java:359) [rt.jar:1.8.0_161]
	at org.jboss.as.controller.services.path.PathInfoHandler.<clinit>(PathInfoHandler.java:86)
	... 14 more
16:53:27,428 FATAL [org.jboss.as.server] WFLYSRV0239: Aborting with exit code 1
16:53:27,478 INFO  [org.jboss.as] WFLYSRV0050: JBoss EAP 7.1.0.GA (WildFly Core 3.0.10.Final-redhat-1) stopped in 34ms

# grep -A4 "Starting oVirt Engine"  /var/log/messages
Apr  9 17:53:22 controller1 systemd: Starting oVirt Engine...
Apr  9 17:53:22 controller1 journal: 2018-04-09 16:53:22,816-0500 ovirt-engine: INFO _detectJBossVersion:187 Detecting JBoss version. Running: /usr/lib/jvm/jre/bin/java ['ovirt-engine-version', '-server', '-XX:+TieredCompilation', '-Xms1024M', '-Xmx1024M', '-Djava.awt.headless=true', '-Dsun.rmi.dgc.client.gcInterval=3600000', '-Dsun.rmi.dgc.server.gcInterval=3600000', '-Djsse.enableSNIExtension=false', '-XX:+HeapDumpOnOutOfMemoryError', '-XX:HeapDumpPath=/var/log/ovirt-engine/dump', '-Djava.util.logging.manager=org.jboss.logmanager', '-Dlogging.configuration=file:///var/lib/ovirt-engine/jboss_runtime/config/ovirt-engine-logging.properties', '-Dorg.jboss.resolver.warning=true', '-Djboss.modules.system.pkgs=org.jboss.byteman', '-Djboss.server.default.config=ovirt-engine', '-Djboss.home.dir=/opt/rh/eap7/root/usr/share/wildfly', '-Djboss.server.base.dir=/usr/share/ovirt-engine', '-Djboss.server.data.dir=/var/lib/ovirt-engine', '-Djboss.server.log.dir=/var/log/ovirt-engine', '-Djboss.server.config.dir=/var/lib/ovirt-engine/jboss_runtime/config', '-Djboss.server.temp.dir=/var/lib/ovirt-engine/jboss_runtime/tmp', '-Djboss.controller.temp.dir=/var/lib/ovirt-engine/jboss_runtime/tmp', '-jar', '/opt/rh/eap7/root/usr/share/wildfly/jboss-modules.jar', '-mp', '/usr/share/ovirt-engine/modules/common:/usr/share/ovirt-engine-extension-aaa-jdbc/modules:/opt/rh/eap7/root/usr/share/wildfly/modules', '-jaxpmodule', 'javax.xml.jaxp-provider', 'org.jboss.as.standalone', '-v']
Apr  9 17:53:24 controller1 journal: 2018-04-09 16:53:24,127-0500 ovirt-engine: INFO _detectJBossVersion:207 Return code: 0,  | stdout: '[u'JBoss EAP 7.1.0.GA (WildFly Core 3.0.10.Final-redhat-1)'],  | stderr: '[]'
Apr  9 17:53:24 controller1 systemd: Started oVirt Engine.
Apr  9 17:53:27 controller1 journal: 2018-04-09 16:53:27,549-0500 ovirt-engine: ERROR run:554 Error: process terminated with status code 1

Comment 5 zzambers 2018-04-10 15:54:34 UTC
Great, there is actually one more component of stacktrace in there:

Caused by: java.time.zone.ZoneRulesException: Unknown time-zone ID: EST
	at java.time.zone.ZoneRulesProvider.getProvider(ZoneRulesProvider.java:272) [rt.jar:1.8.0_161]
	at java.time.zone.ZoneRulesProvider.getRules(ZoneRulesProvider.java:227) [rt.jar:1.8.0_161]
	at java.time.ZoneRegion.ofId(ZoneRegion.java:120) [rt.jar:1.8.0_161]
	at java.time.ZoneId.of(ZoneId.java:411) [rt.jar:1.8.0_161]
	at java.time.ZoneId.of(ZoneId.java:359) [rt.jar:1.8.0_161]
	at org.jboss.as.controller.services.path.PathInfoHandler.<clinit>(PathInfoHandler.java:86)
	... 14 more


So it looks like (equivalent of) ZoneId.of("EST") is called here directly by JBossAS/wildfly. 

After looking to older version of wildfly (3.1.0.Final). It seems, I have found the problematic expression (same class, same line number) [1]. I don't think this is expected to work with "EST", and that 2 argument method ZoneId.of needs to be used to make it work with legacy short locales, as I noted earlier.
( Or alternatively use some alternative mechanism to obtain ZoneId object. )

[1] https://github.com/wildfly/wildfly-core/blob/3.1.0.Final/controller/src/main/java/org/jboss/as/controller/services/path/PathInfoHandler.java#L86

Comment 6 zzambers 2018-04-10 16:28:05 UTC
^^ Or alternatively to use some other mechanism...

Comment 8 Andrew John Hughes 2020-06-09 19:39:09 UTC
Any update on this bug? It seems like a JBoss bug, rather than an OpenJDK issue.

Comment 9 Bernie Hoefer 2020-06-19 02:18:48 UTC
(In reply to Andrew John Hughes from comment #8)
> Any update on this bug? It seems like a JBoss bug, rather than an OpenJDK
> issue.

Andrew, I apologize.  Time got away from me in regards to your 2020-06-09 question.

I rebuilt my January 2018 RHV cluster to now be a self-hosted one.  Although my (virtual) RHV Manager has the same localtime setup:


# ll -d /etc/localtime 
lrwxrwxrwx. 1 root root 23 Jun 28  2019 /etc/localtime -> /usr/share/zoneinfo/EST


...things seem to be working just fine with it.  I am able to stop, start & restart the ovirt-engine.service with no time-zone errors.  Come to think of it, I don't remember encountering this problem under this new build.  So, whatever/however it got fixed, it has been fixed since I built this self-hosted RHV 4.3.9.4-11.el7 cluster in June 2019.

Thanks for following up.

Comment 10 Andrew John Hughes 2020-06-22 15:02:40 UTC
Thanks, Bernie. Good to hear it's working for you now.

Am I ok to close this bug then?

Comment 11 Bernie Hoefer 2020-06-22 15:24:01 UTC
(In reply to Andrew John Hughes from comment #10)

> Am I ok to close this bug then?

Yes; thank you all for your help and past attention on this.