rbeckman-nextgen / test-mc6

0 stars 0 forks source link

When Async Operations Is Enabled In Dicom Listener SQL Deadlocks Result in Dataloss #4325

Open rbeckman-nextgen opened 4 years ago

rbeckman-nextgen commented 4 years ago

When enabling max processing threads and max async operations sporadically after receiving over 20,000 dicom images 96 of the transfers indicated a SQL deadlock error , walking through the code it appears this results in complete dataloss and the dicom client on the other end is getting a success back. This is a major issue.

[2019-11-13 07:51:30,922] ERROR (com.mirth.connect.donkey.server.channel.Channel:1288): Error processing message in channel ------ (94551f18-3434-47ee-89ba-56c6d75e2a9a). com.mirth.connect.donkey.server.channel.ChannelException: at com.mirth.connect.donkey.server.channel.Channel.dispatchRawMessage(Channel.java:1243) at com.mirth.connect.donkey.server.channel.SourceConnector.dispatchRawMessage(SourceConnector.java:192) at com.mirth.connect.donkey.server.channel.SourceConnector.dispatchRawMessage(SourceConnector.java:170) at org.dcm4che2.tool.dcmrcv.MirthDcmRcv.onCStoreRQ(MirthDcmRcv.java:158) at org.dcm4che2.tool.dcmrcv.StorageSCP.onCStoreRQ(StorageSCP.java:96) at org.dcm4che2.tool.dcmrcv.StorageSCP.cstore(StorageSCP.java:73) at org.dcm4che2.net.DicomServiceRegistry.process(DicomServiceRegistry.java:238) at org.dcm4che2.net.NetworkApplicationEntity.perform(NetworkApplicationEntity.java:1185) at org.dcm4che2.net.Association.onDimseRQ(Association.java:1010) at org.dcm4che2.net.PDUDecoder.decodeDIMSE(PDUDecoder.java:530) at org.dcm4che2.net.Association.onPDataTF(Association.java:987) at org.dcm4che2.net.State$Sta6.receivedPDataTF(State.java:239) at org.dcm4che2.net.Association.receivedPDataTF(Association.java:983) at org.dcm4che2.net.PDUDecoder.nextPDU(PDUDecoder.java:231) at org.dcm4che2.net.Association.run(Association.java:882) at java.lang.Thread.run(Thread.java:748)Caused by: com.mirth.connect.donkey.server.data.DonkeyDaoException: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction at com.mirth.connect.donkey.server.data.jdbc.JdbcDao.insertContent(JdbcDao.java:287) at com.mirth.connect.donkey.server.data.jdbc.JdbcDao.updateMap(JdbcDao.java:1044) at com.mirth.connect.donkey.server.data.jdbc.JdbcDao.updateSourceMap(JdbcDao.java:1059) at com.mirth.connect.donkey.server.data.jdbc.JdbcDao.insertConnectorMessage(JdbcDao.java:817) at com.mirth.connect.donkey.server.data.buffered.BufferedDao.executeTasks(BufferedDao.java:109) at com.mirth.connect.donkey.server.data.buffered.BufferedDao.commit(BufferedDao.java:85) at com.mirth.connect.donkey.server.data.buffered.BufferedDao.commit(BufferedDao.java:72) at com.mirth.connect.donkey.server.channel.Channel.dispatchRawMessage(Channel.java:1215) ... 15 moreCaused by: com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at com.mysql.jdbc.Util.handleNewInstance(Util.java:408) at com.mysql.jdbc.Util.getInstance(Util.java:383) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1074) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4208) at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:4140) at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2597) at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2758) at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2826) at com.mysql.jdbc.PreparedStatement.executeInternal(PreparedStatement.java:2082) at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2334) at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2262) at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:2246) at com.mirth.connect.donkey.server.data.jdbc.JdbcDao.insertContent(JdbcDao.java:284)

Imported Issue. Original Details: Jira Issue Key: MIRTH-4474 Reporter: devinsoares Created: 2019-11-14T06:50:50.000-0800

rbeckman-nextgen commented 4 years ago

Devin 3:25 PM @agermano it would depend on the source connector settings , no? Going to lower my thread count to see if that helps.. agermano 3:31 PM Not really. DcmRcv runs in it's own thread and receives messages, which it then dispatches to the channel. Your source connector response selection is basically ignored for a Dicom Receiver. If it were to use your selected response, you'd have to be constructing valid dicom responses for it to send back. Devin 3:51 PM Yeah ok, turning off threading for now. Maybe someone from the Mirth team could look in to this? @narupley? jonb:house_with_garden: 3:53 PM Is source queuing on? Devin 3:54 PM No Just async operations are set. Rather were set, reverting to single thread. agermano 4:23 PM @Devin I'm pretty sure the message gets swallowed when you get that error https://github.com/nextgenhealthcare/connect/blob/3.7.1/donkey/src/main/java/com/mirth/connect/donkey/server/channel/Channel.java#L1288 GitHubGitHub nextgenhealthcare/connect The swiss army knife of healthcare integration. Contribute to nextgenhealthcare/connect development by creating an account on GitHub. There is where it logs the error then it either rethrows the exception or returns a new result containing the exception which is probably great for most source connectors but if you follow the stack trace up, here is where it's calling dispatch https://github.com/nextgenhealthcare/connect/blob/3.7.1/server/src/org/dcm4che2/tool/dcmrcv/MirthDcmRcv.java#L158 GitHubGitHub nextgenhealthcare/connect The swiss army knife of healthcare integration. Contribute to nextgenhealthcare/connect development by creating an account on GitHub. if it gets a ChannelException, it catches and swallows on line 162 (edited) It doesn't really do anything with the DispatchResult either The DicomObject rsp parameter being passed into that function is initialized as a dicom success. This method doesn't do anything to that object at all, but I think they should be modifying it to indicate a failure to store. http://bradleyross.users.sourceforge.net/docs/dicom/doc/src-html/org/dcm4che2/tool/dcmrcv/StorageSCP.html Line 74 is where that object is created (edited) because right after it calls MirthDcmRcv.onCStoreRQ it writes that (SUCCESS) response to the Association. (edited) Devin 4:45 PM Swallowed meaning gone for good and not processed? agermano 5:02 PM That's how I'm reading it

Imported Comment. Original Details: Author: devinsoares Created: 2019-11-14T07:42:39.000-0800