wkim / h2database

Automatically exported from code.google.com/p/h2database
0 stars 0 forks source link

Questionable implementation of MathUtils.generateAlternativeSeed; logs misleading "java.io.UTFDataFormatException: encoded string too long" to stdout #374

Closed GoogleCodeExporter closed 8 years ago

GoogleCodeExporter commented 8 years ago
What steps will reproduce the problem?
(simple SQL scripts or simple standalone applications are preferred)
1. start application with many system properties (total length of keys and 
values need to exceed 64kb)
2. create a table that uses auto increment for its primary key

What is the expected output? What do you see instead?

A misleading warning is logged to stdout, because on  
System.getProperties().toString() yields a string that exceeds 64kb leading to 
an exception in DataOutputStream.writeUTF() which is caught and "logged" by 
calling t.printStackTrace():

Warning: generateAlternativeSeed
java.io.UTFDataFormatException: encoded string too long: 69348 bytes
    at java.io.DataOutputStream.writeUTF(DataOutputStream.java:347)
    at java.io.DataOutputStream.writeUTF(DataOutputStream.java:306)
    at org.h2.util.MathUtils.generateAlternativeSeed(MathUtils.java:136)
    at org.h2.util.MathUtils.getSecureRandom(MathUtils.java:87)
    at org.h2.util.MathUtils.secureRandomLong(MathUtils.java:336)
    at org.h2.value.ValueUuid.getNewRandom(ValueUuid.java:50)
    at org.h2.table.Column.convertAutoIncrementToSequence(Column.java:369)
    at org.h2.command.ddl.CreateTable.update(CreateTable.java:139)
    at org.h2.command.CommandContainer.update(CommandContainer.java:73)
    at org.h2.command.Command.executeUpdate(Command.java:226)
    at org.h2.jdbc.JdbcStatement.executeUpdateInternal(JdbcStatement.java:125)
    at org.h2.jdbc.JdbcStatement.executeUpdate(JdbcStatement.java:110)
    at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:383)
    at org.hibernate.tool.hbm2ddl.SchemaExport.create(SchemaExport.java:341)
    at org.hibernate.tool.hbm2ddl.SchemaExport.execute(SchemaExport.java:262)
    at org.hibernate.tool.hbm2ddl.SchemaExport.create(SchemaExport.java:211)
    at org.hibernate.impl.SessionFactoryImpl.<init>(SessionFactoryImpl.java:392)
    at org.hibernate.cfg.Configuration.buildSessionFactory(Configuration.java:1385)
    at org.hibernate.cfg.AnnotationConfiguration.buildSessionFactory(AnnotationConfiguration.java:954)
    at org.hibernate.ejb.Ejb3Configuration.buildEntityManagerFactory(Ejb3Configuration.java:892)
    at org.hibernate.ejb.HibernatePersistence.createContainerEntityManagerFactory(HibernatePersistence.java:74)
    at org.springframework.orm.jpa.LocalContainerEntityManagerFactoryBean.createNativeEntityManagerFactory(LocalContainerEntityManagerFactoryBean.java:225)
    at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.afterPropertiesSet(AbstractEntityManagerFactoryBean.java:310)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.invokeInitMethods(AbstractAutowireCapableBeanFactory.java:1479)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.initializeBean(AbstractAutowireCapableBeanFactory.java:1419)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:518)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:455)
    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:293)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:290)
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:192)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:567)
    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:895)
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:425)
    at org.springframework.test.context.support.AbstractGenericContextLoader.loadContext(AbstractGenericContextLoader.java:84)
    at org.springframework.test.context.support.AbstractGenericContextLoader.loadContext(AbstractGenericContextLoader.java:1)
    at org.springframework.test.context.TestContext.loadApplicationContext(TestContext.java:280)
    at org.springframework.test.context.TestContext.getApplicationContext(TestContext.java:304)
    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.injectDependencies(DependencyInjectionTestExecutionListener.java:109)
    at org.springframework.test.context.support.DependencyInjectionTestExecutionListener.prepareTestInstance(DependencyInjectionTestExecutionListener.java:75)
    at org.springframework.test.context.TestContextManager.prepareTestInstance(TestContextManager.java:321)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.createTest(SpringJUnit4ClassRunner.java:211)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner$1.runReflectiveCall(SpringJUnit4ClassRunner.java:287)
    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.methodBlock(SpringJUnit4ClassRunner.java:289)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.runChild(SpringJUnit4ClassRunner.java:231)
    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:47)
    at org.junit.runners.ParentRunner$3.run(ParentRunner.java:231)
    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:60)
    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:229)
    at org.junit.runners.ParentRunner.access$000(ParentRunner.java:50)
    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:222)
    at org.springframework.test.context.junit4.statements.RunBeforeTestClassCallbacks.evaluate(RunBeforeTestClassCallbacks.java:61)
    at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:70)
    at org.junit.runners.ParentRunner.run(ParentRunner.java:300)
    at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:174)
    at org.apache.maven.surefire.junit4.JUnit4Provider.execute(JUnit4Provider.java:234)
    at org.apache.maven.surefire.junit4.JUnit4Provider.executeTestSet(JUnit4Provider.java:133)
    at org.apache.maven.surefire.junit4.JUnit4Provider.invoke(JUnit4Provider.java:114)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at org.apache.maven.surefire.util.ReflectionUtils.invokeMethodWithArray(ReflectionUtils.java:188)
    at org.apache.maven.surefire.booter.ProviderFactory$ProviderProxy.invoke(ProviderFactory.java:166)
    at org.apache.maven.surefire.booter.ProviderFactory.invokeProvider(ProviderFactory.java:86)
    at org.apache.maven.surefire.booter.ForkedBooter.runSuitesInProcess(ForkedBooter.java:101)
    at org.apache.maven.surefire.booter.ForkedBooter.main(ForkedBooter.java:74)

What version of the product are you using? On what operating system, file
system, and virtual machine?
h2 1.3.163, also happened with 1.2.147.
Java 1.6u29. Windows7 x64 Enterprise.

Do you know a workaround?
No. Using less system properties is not an option because they are there for a 
reason!

How important/urgent is the problem for you?
medium-low

Please provide any additional information below.

I have a couple of objections and suggestions regarding the implementation of 
MathUtils.generateAlternativeSeed():

1. For Java 1.5 and upwards you could/should just use java.util.UUID. It does 
all the stuff like adding the hostname etc. which you are now calculating 
"manually".

2. If 1. is not an option:
You should not rely on toString of the system properties because of the 
possible length problem.
If you do need the system properties, then please consider using just 
hashCode(), not toString().

3. If 2. is not an option and you decide to stick with the current 
implementation of generateAlternativeSeed():
Please remove the printout of the whole exception to stdout. Ideally, get rid 
of "logging" to stdout completely. If you need to log something, then please 
use a proper logging framework.

Thanks!

Original issue reported on code.google.com by moldowan.android@googlemail.com on 23 Jan 2012 at 9:27

GoogleCodeExporter commented 8 years ago
Sorry, I forgot to insert some words in "What do you see instead?":

_A misleading warning is logged to stdout, because on *MathUtils.java:136* 
System.getProperties().toString() yields ..._

Original comment by moldowan.android@googlemail.com on 23 Jan 2012 at 9:31

GoogleCodeExporter commented 8 years ago
Hi,

Thanks for reporting this issue. MathUtils.generateAlternativeSeed is only used 
if the following code takes more than 200 ms:

SecureRandom.getInstance("SHA1PRNG").generateSeed(20);

This in turn only occurs when reading from /dev/random is very slow, which is 
very rare. Using UUID.randomUUID() wouldn't help because this also reads from 
/dev/random. Using log4j isn't an option because the database engine can't have 
such hard dependencies. Not logging isn't an option because it's a potential 
security problem (insecure random seed). I will fix this issue as follows:
// environment

try {
    String s = System.getProperties().toString();
    // can't use writeUTF, as the string
    // might be larger than 64 KB
    out.writeInt(s.length());
    out.write(s.getBytes("UTF-8"));
} catch (Exception e) {
    warn("generateAlternativeSeed", e);
}

Original comment by thomas.t...@gmail.com on 24 Jan 2012 at 8:01

GoogleCodeExporter commented 8 years ago
Thanks for the quick response and the explanations!

This explains why we didn't see this exception in the past: We are currently 
experiencing less than stellar performance from out Hudson CI machine which 
runs the tests. So this is why the fallback kicks in (more often).

Fix looks ok to me.

I respect your decision to not use a logging framework.
slf4j and logback might be worth a look, nevertheless. ;)

Original comment by moldowan.android@googlemail.com on 24 Jan 2012 at 10:16

GoogleCodeExporter commented 8 years ago
Should be fixed in version 1.3.164

> slf4j and logback might be worth a look, nevertheless. ;)

Actually SLF4J is supported, but it's optional - see 
http://www.h2database.com/html/features.html#other_logging

Possibly reading from /dev/random is slow on your machine? That could cause 
other Java programs to slow down a lot - but I'm not sure if there is a 
workaround

Original comment by thomas.t...@gmail.com on 3 Feb 2012 at 2:18

GoogleCodeExporter commented 8 years ago
Fix confirmed, thanks!

It seems like /dev/random isn't producing anything, whereas /dev/urandom does 
produce a lot of bytes.
Maybe we need something like: http://www.vanheusden.com/te/

Original comment by moldowan.android@googlemail.com on 6 Feb 2012 at 7:09