OverlappingFileLockException при использовании H2 db из приложения Clojure / JVM, работающего в Docker со службой приложений Azure в Linux - PullRequest
Новая
       58

OverlappingFileLockException при использовании H2 db из приложения Clojure / JVM, работающего в Docker со службой приложений Azure в Linux

0 голосов
/ 10 октября 2019

Полное название / сводка:

OverlappingFileLockException при использовании базы данных H2 в автономном приложении Clojure / JVM (встроенный сервер httpkit), работающем в контейнере Docker со службой приложений Azure в Linux и Persisted SharedХранилище

Intro

Примечание: Первоначально я подал это как проблему в базу данных H2 github repo , но я публикую ее здесь после сбора более подробной информациив надежде, что я смогу получить больше советов о том, как действовать.

Я устранял проблемы, связанные с ненадлежащим OverlappingFileLockException выбросом драйвера JDBC H2 при запуске нашего приложения со службой приложений Azure в Linux.

Мы используем H2 в режиме «внедренного файла» с DB_CLOSE_DELAY=0 (по умолчанию: новая транзакция должна открывать совершенно новое соединение БД, потому что старое уже закрыто) и MULTI_THREADED=1;В настоящее время мы проводим тестирование с последней стабильной версией 1.4.199.

Мы получили отчеты от двух независимых пользователей, работающих с очень похожей установкой Azure. Мы не получали такого отчета от других пользователей, работающих с этим приложением.

Подробности Env

  • Версия встроенной базы данных H2: 1.4.199
  • Служба приложений Azureс числом экземпляров, ограниченным 1, и WEBSITES_ENABLE_APP_SERVICE_STORAGE = true
    • файл БД находится на смонтированном томе /home, который, на мой взгляд, находится в файлах Azure, поддерживаемых распределенной файловой системой, говорящей по протоколу SMB.
    • Том /home автоматически монтируется Azure как именованный (?) Том докера внутри контейнера (см. https://docs.microsoft.com/en-us/azure/app-service/containers/app-service-linux-faq#custom-containers)
  • Образ докера: ubuntu: 18.10
  • java -version
openjdk version "11.0.1" 2018-10-16
OpenJDK Runtime Environment (build 11.0.1+13-Ubuntu-3ubuntu3.18.10.1)
OpenJDK 64-Bit Server VM (build 11.0.1+13-Ubuntu-3ubuntu3.18.10.1, mixed mode, sharing)

У меня нет доступа ни к хост-компьютеру, ни к общему ресурсу Azure Files, только к SSH-доступу к работающему контейнеру Docker.

Stacktrace 

2019-10-10T06:43:08.432104251Z 2019-10-10 06:43:08.426 07058ebde3f2 pool-23-thread-2 ERROR [<some-backgroun-thread-reading-from-DB>:158] - Failed to do xxx.
2019-10-10T06:43:08.432142451Z                                                          [37mjava.lang.Thread.run[m  [32m                     Thread.java:  834[m
2019-10-10T06:43:08.432149151Z                            [37mjava.util.concurrent.ThreadPoolExecutor$Worker.run[m  [32m         ThreadPoolExecutor.java:  628[m
2019-10-10T06:43:08.432153651Z                             [37mjava.util.concurrent.ThreadPoolExecutor.runWorker[m  [32m         ThreadPoolExecutor.java: 1128[m
2019-10-10T06:43:08.432158251Z      [37mjava.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run[m  [32mScheduledThreadPoolExecutor.java:  305[m
2019-10-10T06:43:08.432162751Z                                   [37mjava.util.concurrent.FutureTask.runAndReset[m  [32m                 FutureTask.java:  305[m
2019-10-10T06:43:08.432167151Z                           [37mjava.util.concurrent.Executors$RunnableAdapter.call[m  [32m                  Executors.java:  515[m

... some app logic ...

2019-10-10T06:43:08.432210251Z                                     [33mclojure.java.jdbc/[1;33mdb-query-with-resultset[m  [32m                        jdbc.clj:  848[m
2019-10-10T06:43:08.432215551Z                                              [33mclojure.java.jdbc/[1;33mget-connection[m  [32m                        jdbc.clj:  272[m
2019-10-10T06:43:08.432226751Z                                          [37mjava.sql.DriverManager.getConnection[m  [32m              DriverManager.java:  189[m
2019-10-10T06:43:08.432230951Z                                          [37mjava.sql.DriverManager.getConnection[m  [32m              DriverManager.java:  677[m
2019-10-10T06:43:08.432234651Z                                                         [37morg.h2.Driver.connect[m  [32m                     Driver.java:   69[m
2019-10-10T06:43:08.432238451Z                                             [37morg.h2.jdbc.JdbcConnection.<init>[m  [32m             JdbcConnection.java:  148[m
2019-10-10T06:43:08.432242451Z                                             [37morg.h2.jdbc.JdbcConnection.<init>[m  [32m             JdbcConnection.java:  169[m
2019-10-10T06:43:08.432246151Z                           [37morg.h2.engine.SessionRemote.connectEmbeddedOrServer[m  [32m              SessionRemote.java:  336[m
2019-10-10T06:43:08.432249951Z                                            [37morg.h2.engine.Engine.createSession[m  [32m                     Engine.java:   31[m
2019-10-10T06:43:08.432253851Z                                            [37morg.h2.engine.Engine.createSession[m  [32m                     Engine.java:  161[m
2019-10-10T06:43:08.432257751Z                                 [37morg.h2.engine.Engine.createSessionAndValidate[m  [32m                     Engine.java:  178[m
2019-10-10T06:43:08.432282951Z                                              [37morg.h2.engine.Engine.openSession[m  [32m                     Engine.java:  201[m
2019-10-10T06:43:08.432286851Z                                              [37morg.h2.engine.Engine.openSession[m  [32m                     Engine.java:   69[m
2019-10-10T06:43:08.432290851Z                                                 [37morg.h2.engine.Database.<init>[m  [32m                   Database.java:  313[m
2019-10-10T06:43:08.432295251Z                                           [37morg.h2.engine.Database.openDatabase[m  [32m                   Database.java:  319[m
2019-10-10T06:43:08.432299351Z                                                   [37morg.h2.engine.Database.open[m  [32m                   Database.java:  769[m
2019-10-10T06:43:08.432303351Z                                           [37morg.h2.engine.Database.getPageStore[m  [32m                   Database.java: 2739[m
2019-10-10T06:43:08.432307151Z                                          [37morg.h2.mvstore.db.MVTableEngine.init[m  [32m              MVTableEngine.java:   95[m
2019-10-10T06:43:08.432311151Z                                    [37morg.h2.mvstore.db.MVTableEngine$Store.open[m  [32m              MVTableEngine.java:  162[m
2019-10-10T06:43:08.432315051Z                                           [37morg.h2.mvstore.MVStore$Builder.open[m  [32m                    MVStore.java: 3343[m
2019-10-10T06:43:08.432321351Z                                                 [37morg.h2.mvstore.MVStore.<init>[m  [32m                    MVStore.java:  390[m
2019-10-10T06:43:08.432325351Z                                                 [37morg.h2.mvstore.FileStore.open[m  [32m                  FileStore.java:  163[m
2019-10-10T06:43:08.432329451Z                                         [37mjava.nio.channels.FileChannel.tryLock[m  [32m                FileChannel.java: 1165[m
2019-10-10T06:43:08.432333251Z                                               [37morg.h2.store.fs.FileNio.tryLock[m  [32m                FilePathNio.java:  121[m
2019-10-10T06:43:08.432337151Z                                            [37msun.nio.ch.FileChannelImpl.tryLock[m  [32m            FileChannelImpl.java: 1154[m
2019-10-10T06:43:08.432340951Z                                                  [37msun.nio.ch.FileLockTable.add[m  [32m              FileLockTable.java:  123[m
2019-10-10T06:43:08.432344851Z                                            [37msun.nio.ch.FileLockTable.checkList[m  [32m              FileLockTable.java:  229[m
2019-10-10T06:43:08.432348851Z     [1;31mjava.nio.channels.OverlappingFileLockException[m: [3m[m
2019-10-10T06:43:08.432352651Z                    [1;31mjava.lang.IllegalStateException[m: [3mThe file is locked: nio:/configuration/myapp.mv.db [1.4.199/7][m
2019-10-10T06:43:08.432356951Z [1;31morg.h2.jdbc.JdbcSQLNonTransientConnectionException[m: [3mDatabase may be already in use: null. Possible solutions: close all other connection(s); use the server mode [90020-199][m
2019-10-10T06:43:08.432361151Z            [1mSQLState[m: "90020"
2019-10-10T06:43:08.432364951Z           [1merrorCode[m: 90020
2019-10-10T06:43:08.432368651Z     [1moriginalMessage[m: "Database may be already in use: null. Possible solutions: close all other connection(s); use the server mode"
2019-10-10T06:43:08.432372751Z

Когда возникает такая ситуация, я даже не могу сделать копию файла db - я полагаю, это потому, что блокировка файлов работает в SMB / Windows: 

root@07058ebde3f2:/configuration# cp my-db.mv.db tmp.bak
cp: error reading 'my-db.mv.db': Permission denied

По документации тИсключение выдается, когда JVM уже удерживает блокировку. Кажется, по какой-то причине эта блокировка не снимается экземпляром org.h2.engine.Database, что должно быть сделано в Database # closeImpl -> ... -> org.h2.mvstore.FileStore #закройте , если правильно понимаете исходный код. Это, в свою очередь, удаляет блокировку, сохраненную в FileLockTable.lockMap (которая была получена ранее путем вызова FileChannel#tryLock) [1].
lockMap является статическим (JVM-широким) полем, хранящим блокировку внутри WeakReference. Это соответствует моим наблюдениям о том, что блокировка действительно снимается, когда выполняется цикл Full GC (например, через jcmd), который заставляет JVM собирать мусор для любых ожидающих WeakReference-s => приложение снова начинает работать должным образом, пока проблема не возникнет снова.

Связь с циклами GC

Как я уже упоминал ранее, проблема, кажется, исчезает, когда я запускаю Full GC. Я взял и проанализировал дамп кучи примерно в то время, когда приложение было сломано, и в FileLockTable.lockMap действительно есть запись, показывающая ссылку на файл БД: Heap Dump - FileLockTable.lockMap

Iподозревать (хотя и не совсем уверенным), что GC (не обязательно Full GC) также является причиной, по которой приложение иногда может "лечить себя";например, на основе журналов, он, казалось, работал правильно в следующие периоды времени (9.10.2019):

  • 00: 01 - 01: 16
  • 01: 16 - 03:08
  • 03: 33: 48 - 04: 25: 08
  • 04: 31: 18 - 04: 49: 09
  • 04: 50: 30 - 04:54:59
  • 04: 55: 58 - 06: 02: 58

Между этими периодами в журналах были частые OverlappingLockException с.

Больше примечаний потестирование и различные эксперименты, которые я провел

Изначально мы использовали версию H2 1.4.193, но я безуспешно пытался переключиться на 1.4.199 (показанная трассировка стека соответствует этой версии).
Я попробовал настройку AUTO_SERVER=TRUE, но ошибка все еще присутствовала (хотя казалось, что приложение могло работать должным образом чаще, чем раньше - возможно, из-за GC, см. Ниже).

Я также пытался сохранить БД в локальном файле в файловой системе контейнера-докера, и это сработало, но это не то, что нам нужно, потому что нам нужно сохранять данные при перезапуске контейнеров (поэтому используется общее хранилище).

Наконец, я попытался воспроизвести это локально, настроив новый общий файловый ресурс на автономном сервере Windows, работающем в Azure, смонтировав его на моей Mac OS и затем передав его как «bind mount» в контейнер Docker, но не сделалполучить сообщение об ошибке в течение 10 часов (в конце концов оно не удалось из-за неисправного монтирования, и демон Docker перестал отвечать полностью и его пришлось уничтожить).

Любые советы о том, как выполнить дальнейшее устранение неполадок, или идеи о том, что может быть не так, высоко ценятся,Например, было бы замечательно, если бы я мог как-то отследить, когда / где была создана блокирующая файл с ошибками, и отследить ее до объекта (если он присутствует в дампе кучи), который его создал.

Спасибо!

[1]: Под капотом tryLock (в Linux) используется системный вызов fcntl - возможно, это одна из причин сохранения существующих блокировок в FileLockTable.lockMapтот факт, что Linux автоматически снимает блокировки файлов, когда системный вызов close вызывается для любого из файловых дескрипторов, используемых для получения блокировки (http://0pointer.de/blog/projects/locking.html).

...