[jira] [Created] (PARQUET-408) Shutdown hook in parquet-avro library corrupts data and disables logging

["Michal Turek (JIRA)" <ji...@apache.org>]

Michal Turek created PARQUET-408:
------------------------------------

             Summary: Shutdown hook in parquet-avro library corrupts data and disables logging
                 Key: PARQUET-408
                 URL: https://issues.apache.org/jira/browse/PARQUET-408
             Project: Parquet
          Issue Type: Bug
          Components: parquet-avro
    Affects Versions: 1.8.1
            Reporter: Michal Turek
             Fix For: 1.9.0
         Attachments: parquet-broken-shutdown_2015-12-16.tar.gz

Parquet-avro and probably also other Parquet libraries are not well behaved. It registers a shutdown hook that bypasses application shutdown sequence, corrupts data written to currently opened Parquet file(s) and disables or reconfigures slf4j/logback logger so no further log message is visible.


h3. Scope

Our application is a microservice that handles stop request in form of signal SIGTERM, resp. JVM shutdown hook. If it arrives the application will close all opened files (writers), release all other resources and gracefully shutdown. We are swiching from sequence files to Parquet at the moment and using Maven dependency {{org.apache.parquet:parquet-avro:1.8.1}} which is current latest version. We are using {{Runtime.getRuntime().addShutdownHook()}} to handle SIGTERM.


h3. Example code

See archive in attachment.

- Optionally update version of {{hadoop-client}} in {{pom.xml}} to match your Hadoop.
- Use {{mvn package}} to compile.
- Copy Hadoop configuration XMLs to {{config}} directory.
- Update configuration at the top of {{ParquetBrokenShutdown}} class.
- Execute {{ParquetBrokenShutdown}} class.
- Send SIGTERM to shutdown the application ({{kill PID}}).


h3. Initial analysis

Parquet library tries to care about application shutdown but this introduces more issues than solves. If application is writing to a file and the library asynchronously decides to close underlying writer, data loss will occur. The handle is just closed and all remaining records can't be written.

{noformat}
Writing to HDFS/Parquet failed
java.io.IOException: can not write PageHeader(type:DICTIONARY_PAGE, uncompressed_page_size:14, compressed_page_size:34, dictionary_page_header:DictionaryPageHeader(num_values:1, encoding:PLAIN))
	at org.apache.parquet.format.Util.write(Util.java:224)
	at org.apache.parquet.format.Util.writePageHeader(Util.java:61)
	at org.apache.parquet.format.converter.ParquetMetadataConverter.writeDictionaryPageHeader(ParquetMetadataConverter.java:760)
	at org.apache.parquet.hadoop.ParquetFileWriter.writeDictionaryPage(ParquetFileWriter.java:307)
	at org.apache.parquet.hadoop.ColumnChunkPageWriteStore$ColumnChunkPageWriter.writeToFileWriter(ColumnChunkPageWriteStore.java:179)
	at org.apache.parquet.hadoop.ColumnChunkPageWriteStore.flushToFileWriter(ColumnChunkPageWriteStore.java:238)
	at org.apache.parquet.hadoop.InternalParquetRecordWriter.flushRowGroupToStore(InternalParquetRecordWriter.java:165)
	at org.apache.parquet.hadoop.InternalParquetRecordWriter.close(InternalParquetRecordWriter.java:113)
	at org.apache.parquet.hadoop.ParquetWriter.close(ParquetWriter.java:297)
	at com.avast.bugreport.parquet.ParquetBrokenShutdown.writeParquetFile(ParquetBrokenShutdown.java:86)
	at com.avast.bugreport.parquet.ParquetBrokenShutdown.run(ParquetBrokenShutdown.java:53)
	at com.avast.bugreport.parquet.ParquetBrokenShutdown.main(ParquetBrokenShutdown.java:153)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:497)
	at com.intellij.rt.execution.application.AppMain.main(AppMain.java:144)
Caused by: parquet.org.apache.thrift.transport.TTransportException: java.nio.channels.ClosedChannelException
	at parquet.org.apache.thrift.transport.TIOStreamTransport.write(TIOStreamTransport.java:147)
	at parquet.org.apache.thrift.transport.TTransport.write(TTransport.java:105)
	at parquet.org.apache.thrift.protocol.TCompactProtocol.writeByteDirect(TCompactProtocol.java:424)
	at parquet.org.apache.thrift.protocol.TCompactProtocol.writeByteDirect(TCompactProtocol.java:431)
	at parquet.org.apache.thrift.protocol.TCompactProtocol.writeFieldBeginInternal(TCompactProtocol.java:194)
	at parquet.org.apache.thrift.protocol.TCompactProtocol.writeFieldBegin(TCompactProtocol.java:176)
	at org.apache.parquet.format.InterningProtocol.writeFieldBegin(InterningProtocol.java:74)
	at org.apache.parquet.format.PageHeader.write(PageHeader.java:918)
	at org.apache.parquet.format.Util.write(Util.java:222)
	... 16 more
Caused by: java.nio.channels.ClosedChannelException
	at org.apache.hadoop.hdfs.DFSOutputStream.checkClosed(DFSOutputStream.java:1635)
	at org.apache.hadoop.fs.FSOutputSummer.write(FSOutputSummer.java:104)
	at org.apache.hadoop.fs.FSDataOutputStream$PositionCache.write(FSDataOutputStream.java:58)
	at java.io.DataOutputStream.write(DataOutputStream.java:107)
	at parquet.org.apache.thrift.transport.TIOStreamTransport.write(TIOStreamTransport.java:145)
	... 24 more
{noformat}

Stored file is also currupted in such case. It contains only four bytes "PAR1" header so actually all data are lost.

Together with that whole application logging using slf4j/logback is reconfigured or completely disabled so no more application's log messages appear in the output. This may be related to PARQUET-369 and will be hopefully fixed in PARQUET-401. No such issue was observed when sequence files were used in the past.


h3. Known workaround

Java executes threads of shutdown hooks independently and in parallel, but it is possible for the application to force its own shutdown to be executed before the Parquet's one. Parquet library uses Hadoop's {{ShutdownHookManager}} to register the hook which has a possibility to define a priority.

{noformat}
if (!USE_WORKAROUND) {
	Runtime.getRuntime().addShutdownHook(shutdownHook);
} else {
	int maxPriority = Integer.MAX_VALUE; // Execute application hook before hook in Hadoop library
	ShutdownHookManager.get().addShutdownHook(shutdownHook, maxPriority);
}
{noformat}

This workaround would be impossible if there are two or more such nasty libraries.

No workaround has been found for the second issue with disabled logging until now.


h3. Suggestions for fix

- Never touch logging configuration in libraries.
-- Use slf4j-api interfaces and just output log messages.
-- Application is responsible for configuration of logging.
- Do not register any shutdown hook in libraries that releases resources that are still possibly in use.
-- Instead provide an API to the application to close/free the allocated resources (already present).
-- The application is responsible to call close on all Closeables during shutdown in correct order and correct time.
-- No library has enough information for that.
- Be well behaved library, do not try to be smarter than the application, it isn't possible.




--
This message was sent by Atlassian JIRA
(v6.3.4#6332)