Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

fix: fix double casting on getTimestamp #326

Merged
merged 1 commit into from
Oct 3, 2023
Merged

fix: fix double casting on getTimestamp #326

merged 1 commit into from
Oct 3, 2023

Conversation

joker1007
Copy link
Contributor

@joker1007 joker1007 commented Oct 3, 2023 •
edited
Loading

in order to avoid to abort retrying.

Because a timestamp is casted to Instant and retain it on MemoryRecord,
but MemoryRecord tries to cast from Timestamp to Instant and raises ClassCastException.
And so, retryExecutor abort on the first retry.

error log with #325

2023-10-02 09:51:58.971 2023-10-02 09:51:58.971 +0000 [INFO] (0019:task-0012): > 0.86 seconds (loaded 3,744 rows in total)
2023-10-02 09:51:59.375 2023-10-02 09:51:59.376 +0000 [ERROR] (0018:task-0013): Operation failed (first exception:{SQLState=1213, ErrorCode=40001})
2023-10-02 09:51:59.375 java.sql.BatchUpdateException: Deadlock found when trying to get lock; try restarting transaction
2023-10-02 09:51:59.375 	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
2023-10-02 09:51:59.375 	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
2023-10-02 09:51:59.375 	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
2023-10-02 09:51:59.377 	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.Util.getInstance(Util.java:408)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.SQLError.createBatchUpdateException(SQLError.java:1162)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.StatementImpl.handleExceptionForBatch(StatementImpl.java:1290)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.PreparedStatement.executeBatchedInserts(PreparedStatement.java:1550)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.PreparedStatement.executeBatchInternal(PreparedStatement.java:1253)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.StatementImpl.executeBatch(StatementImpl.java:970)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.StandardBatchInsert.flush(StandardBatchInsert.java:82)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$PluginPageOutput$1.run(AbstractJdbcOutputPlugin.java:1192)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$RetryableSQLExecution.call(AbstractJdbcOutputPlugin.java:1343)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$RetryableSQLExecution.call(AbstractJdbcOutputPlugin.java:1331)
2023-10-02 09:51:59.377 	at org.embulk.util.retryhelper.RetryExecutor.run(RetryExecutor.java:109)
2023-10-02 09:51:59.377 	at org.embulk.util.retryhelper.RetryExecutor.runInterruptible(RetryExecutor.java:90)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin.withRetry(AbstractJdbcOutputPlugin.java:1309)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin.withRetry(AbstractJdbcOutputPlugin.java:1301)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$PluginPageOutput.flush(AbstractJdbcOutputPlugin.java:1182)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$PluginPageOutput.add(AbstractJdbcOutputPlugin.java:1173)
2023-10-02 09:51:59.377 	at org.embulk.spi.PageBuilderImpl.doFlush(PageBuilderImpl.java:244)
2023-10-02 09:51:59.377 	at org.embulk.spi.PageBuilderImpl.flush(PageBuilderImpl.java:249)
2023-10-02 09:51:59.377 	at org.embulk.spi.PageBuilderImpl.addRecord(PageBuilderImpl.java:228)
2023-10-02 09:51:59.377 	at org.embulk.spi.PageBuilder.addRecord(PageBuilder.java:220)
2023-10-02 09:51:59.377 	at org.embulk.parser.avro.AvroParserPlugin.run(AvroParserPlugin.java:232)
2023-10-02 09:51:59.377 	at org.embulk.spi.FileInputRunner.run(FileInputRunner.java:138)
2023-10-02 09:51:59.377 	at org.embulk.spi.util.ExecutorsInternal.process(ExecutorsInternal.java:60)
2023-10-02 09:51:59.377 	at org.embulk.spi.util.ExecutorsInternal.process(ExecutorsInternal.java:37)
2023-10-02 09:51:59.377 	at org.embulk.exec.LocalExecutorPlugin$DirectExecutor$1.call(LocalExecutorPlugin.java:194)
2023-10-02 09:51:59.377 	at org.embulk.exec.LocalExecutorPlugin$DirectExecutor$1.call(LocalExecutorPlugin.java:191)
2023-10-02 09:51:59.377 	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2023-10-02 09:51:59.377 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2023-10-02 09:51:59.377 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2023-10-02 09:51:59.377 	at java.base/java.lang.Thread.run(Thread.java:829)
2023-10-02 09:51:59.377 Caused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction
2023-10-02 09:51:59.377 	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
2023-10-02 09:51:59.377 	at java.base/jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
2023-10-02 09:51:59.377 	at java.base/jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
2023-10-02 09:51:59.377 	at java.base/java.lang.reflect.Constructor.newInstance(Constructor.java:490)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.Util.handleNewInstance(Util.java:425)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.Util.getInstance(Util.java:408)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:951)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3973)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:3909)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2527)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2680)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2487)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:1858)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2079)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.PreparedStatement.executeUpdateInternal(PreparedStatement.java:2013)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.PreparedStatement.executeLargeUpdate(PreparedStatement.java:5104)
2023-10-02 09:51:59.377 	at com.mysql.jdbc.PreparedStatement.executeBatchedInserts(PreparedStatement.java:1548)
2023-10-02 09:51:59.377 	... 26 common frames omitted
2023-10-02 09:51:59.377 2023-10-02 09:51:59.376 +0000 [ERROR] (0018:task-0013): Operation failed (last exception)
2023-10-02 09:51:59.377 java.lang.ClassCastException: class java.time.Instant cannot be cast to class org.embulk.spi.time.Timestamp (java.time.Instant is in module java.base of loader 'bootstrap'; org.embulk.spi.time.Timestamp is in unnamed module of loader 'app')
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.MemoryRecord.getTimestamp(MemoryRecord.java:44)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.setter.ColumnSetterVisitor.timestampColumn(ColumnSetterVisitor.java:104)
2023-10-02 09:51:59.377 	at org.embulk.spi.Column.visit(Column.java:77)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$PluginPageOutput.retryColumnsSetters(AbstractJdbcOutputPlugin.java:1265)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$PluginPageOutput$1.run(AbstractJdbcOutputPlugin.java:1189)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$RetryableSQLExecution.call(AbstractJdbcOutputPlugin.java:1343)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$RetryableSQLExecution.call(AbstractJdbcOutputPlugin.java:1331)
2023-10-02 09:51:59.377 	at org.embulk.util.retryhelper.RetryExecutor.run(RetryExecutor.java:109)
2023-10-02 09:51:59.377 	at org.embulk.util.retryhelper.RetryExecutor.runInterruptible(RetryExecutor.java:90)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin.withRetry(AbstractJdbcOutputPlugin.java:1309)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin.withRetry(AbstractJdbcOutputPlugin.java:1301)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$PluginPageOutput.flush(AbstractJdbcOutputPlugin.java:1182)
2023-10-02 09:51:59.377 	at org.embulk.output.jdbc.AbstractJdbcOutputPlugin$PluginPageOutput.add(AbstractJdbcOutputPlugin.java:1173)
2023-10-02 09:51:59.377 	at org.embulk.spi.PageBuilderImpl.doFlush(PageBuilderImpl.java:244)
2023-10-02 09:51:59.377 	at org.embulk.spi.PageBuilderImpl.flush(PageBuilderImpl.java:249)
2023-10-02 09:51:59.377 	at org.embulk.spi.PageBuilderImpl.addRecord(PageBuilderImpl.java:228)
2023-10-02 09:51:59.377 	at org.embulk.spi.PageBuilder.addRecord(PageBuilder.java:220)
2023-10-02 09:51:59.377 	at org.embulk.parser.avro.AvroParserPlugin.run(AvroParserPlugin.java:232)
2023-10-02 09:51:59.377 	at org.embulk.spi.FileInputRunner.run(FileInputRunner.java:138)
2023-10-02 09:51:59.377 	at org.embulk.spi.util.ExecutorsInternal.process(ExecutorsInternal.java:60)
2023-10-02 09:51:59.377 	at org.embulk.spi.util.ExecutorsInternal.process(ExecutorsInternal.java:37)
2023-10-02 09:51:59.377 	at org.embulk.exec.LocalExecutorPlugin$DirectExecutor$1.call(LocalExecutorPlugin.java:194)
2023-10-02 09:51:59.377 	at org.embulk.exec.LocalExecutorPlugin$DirectExecutor$1.call(LocalExecutorPlugin.java:191)
2023-10-02 09:51:59.377 	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
2023-10-02 09:51:59.377 	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
2023-10-02 09:51:59.377 	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
2023-10-02 09:51:59.377 	at java.base/java.lang.Thread.run(Thread.java:829)

@joker1007
fix: fix double casting on getTimestamp
318f97f 
in order to avoid to abort retrying.

Because a timestamp is casted to Instant and retain it on MemoryRecord,
but MemoryRecord tries to cast from Timestamp to Instant and raises
ClassCastException.
And so, retryExecutor abort on the first retry.
@dmikurube dmikurube requested a review from a team October 3, 2023 07:11
@dmikurube dmikurube added this to the v0.10.3 milestone Oct 3, 2023
dmikurube
dmikurube approved these changes Oct 3, 2023
View reviewed changes
Copy link
Member

@dmikurube dmikurube left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ugh, Instant has been set there, so the receiver would have to expect Instant, not Timestamp...

Thanks! It was a bug when converting Timestamp to Instant. Type-checking is bypassed through Object... :(

@joker1007 joker1007 merged commit c2acb83 into embulk:master Oct 3, 2023
4 checks passed
@joker1007 joker1007 deleted the fix-timestamp-casting branch October 3, 2023 08:39
@dmikurube
Copy link
Member

jfyi, this has been released as a part of v0.10.3!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@dmikurube dmikurube dmikurube approved these changes

Assignees
No one assigned
Labels
None yet
Milestone
v0.10.3
Development

Successfully merging this pull request may close these issues.
2 participants
@joker1007 @dmikurube