Spring Data MongoRepository save (T) не работает ... иногда
Итак, есть небольшое приложение Angular + Java + Spring Boot + MongoDB, с которым я работаю. В последнее время он получает довольно много действий (читай: модификации кода), но классы доступа к данным остались в основном нетронутыми AFAIK.
Однако похоже, что MongoRepository внезапно решил прекратить сохранять изменения, которые я save() делаю в БД.
Проверяя mongod.log, вот что я вижу, когда save() работает:
2018-04-11T15:04:06.840+0200 I COMMAND [conn6] command pdfviewer.bookData command: find { find: "bookData", filter: { _id: "ID_1" }, limit: 1, singleBatch: true } planSummary: IDHACK keysExamined:1 docsExamined:1 idhack:1 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:1 nreturned:1 reslen:716 locks:{ Global: { acquireCount: { r: 4 } }, Database: { acquireCount: { r: 2 } }, Collection: { acquireCount: { r: 2 } } } protocol:op_query 102ms
2018-04-11T17:30:19.615+0200 I WRITE [conn7] update pdfviewer.bookData query: { _id: "ID_1" } update: { _class: "model.BookData", _id: "ID_1", config: { mode: "normal", offlineEnabled: true }, metadata: { title: "PDFdePrueba3pag copia 6 ", ...}, downloaded: false, currentPageNumber: 2, availablePages: 3, bookmarks: [], stats: { _id: "c919e517-3c68-462c-8396-d4ba391762e6", dateOpen: new Date(1523460575872), dateClose: new Date(1523460575951), timeZone: "+2", ... }, ... } keysExamined:1 docsExamined:1 nMatched:1 nModified:1 keyUpdates:0 writeConflicts:1 numYields:1 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } } } 315ms
2018-04-11T17:30:19.615+0200 I COMMAND [conn7] command pdfviewer.$cmd command: update { update: "bookData", ordered: false, updates: [ { q: { _id: "ID_1" }, u: { _class: "model.BookData", _id: "ID_1", config: { mode: "normal", offlineEnabled: true }, metadata: { title: "PDFdePrueba3pag copia 6 ", ...}, downloaded: false, currentPageNumber: 2, availablePages: 3, bookmarks: [], stats: { _id: "c919e517-3c68-462c-8396-d4ba391762e6", dateOpen: new Date(1523460575872), dateClose: new Date(1523460575951), timeZone: "+2", ... }, ... }, upsert: true } ] } keyUpdates:0 writeConflicts:0 numYields:0 reslen:55 locks:{ Global: { acquireCount: { r: 2, w: 2 } }, Database: { acquireCount: { w: 2 } }, Collection: { acquireCount: { w: 2 } } } protocol:op_query 316ms
И вот что я вижу, когда этого не происходит:
2018-04-11T18:13:21.864+0200 I NETWORK [initandlisten] connection accepted from 127.0.0.1:64271 #1 (1 connection now open)
2018-04-11T18:18:51.425+0200 I NETWORK [initandlisten] connection accepted from 127.0.0.1:64329 #2 (2 connections now open)
2018-04-11T18:19:06.967+0200 I NETWORK [initandlisten] connection accepted from 127.0.0.1:64346 #3 (3 connections now open)
Выполнив tail -f1 в файле журнала во время отладки, я увидел, что эти соединения появляются правильно, когда мой код вызывает findById() или save(), поэтому кажется, что приложение может достичь БД.
Это (более или менее) соответствующий Java-код:
/* BookData.java */
@Document
public class BookData {
@Id private String id;
// Some more non-Id Strings...
private Config config;
private Metadata metadata;
private Boolean downloaded;
private Integer currentPageNumber;
private int availablePages;
private List<Bookmark> bookmarks;
private StatsModel stats;
@Transient private byte[] contents;
public BookData() {}
// getters and setters
}
/* BookDataRepository.java */
// MongoRepository comes from spring-boot-starter-parent-1.4.5.RELEASE
public interface BookDataRepository extends MongoRepository<BookData, String> {
BookData findById(String id);
}
/* BookDataServiceImpl.java */
public BookData updateBookData(String id, BookData newData) {
final BookData original = bookDataRepository.findById(id);
if (original == null) {
return null;
}
original.setCurrentPageNumber(Optional.ofNullable(newData.getCurrentPageNumber()).orElseGet(original::getCurrentPageNumber));
// similar code for a couple other fields
return bookDataRepository.save(original);
}
Я прошел через эту часть сотни раз во время отладки, и вроде все в порядке:
findById(id)правильно возвращает ожидаемый объектBookData original: проверьте ✓newDataсодержит ожидаемые значения, которые будут использоваться для обновления: отметьте ✓- непосредственно перед вызовом
save(original),originalбыл правильно изменен с использованием значенийnewData: проверьте ✓ save()работает без ошибок: проверьте ✓save()возвращает новыйBookDataс правильно обновленными значениями: к моему собственному удивлению, отметьте ✓- после возврата
save()запросdb.bookData.find()в Mongo Shell показывает, что значения были обновлены: неудача. - после того, как
save()возвращается, объектBookData, полученный новыми вызовамиfindById(), содержит обновленные значения: неудача (иногда да, иногда нет).
Просто похоже, что MongoDB ждет какой-то flush(), но это не репозиторий JPA, где вместо этого можно было бы вызвать saveAndFlush().
Есть идеи, почему это может происходить?
Обновлено: версии (по запросу):
- Java 8
- Весенний ботинок 1.4.5
- MongoDB 3.2.6
- Windows 10
Я также включил BookData выше.
Я предлагаю вам добавить туда несколько журналов в updateBookData, так как есть нулевая проверка и в некоторых случаях оригинал останется нетронутым. зарегистрируйте bean-компонент перед внесением изменений и прямо перед тем, как save может помочь при ошибках приложения. Можете выложить свой бин BookData ?
Вы настроили политики WriteResultChecking или WriteConcern?
@Paizo Спасибо за ваше участие. Используя пошаговое выполнение, я подтвердил, что original модифицируется, как ожидалось, до save (как указано в вопросе), так что это не проблема. Я добавлю BookData по запросу.
@AnatolyShamov Нет, все, что касается Spring Data и MongoRepository, настолько ванильно, насколько это возможно.
@LuisG., Можете еще добавить информацию о сервере mongo? Версия, ОС и т. д.
@TarunLalwani Готово.
Можете ли вы попробовать с MongoDB 3.4 или 3.6? docs.mongodb.com/manual/tutorial/install-mongodb-on-windows
@LuisG. У вас есть тестовый пример, чтобы достоверно воспроизвести проблему?
@TarunLalwani Наш производственный экземпляр MongoDB используется несколькими приложениями, включая мое, поэтому обновление до 3.4 или 3.6 потребует значительных усилий со стороны других команд для тестирования своих приложений на соответствие новой версии и т. д. - чего я бы предпочел пока избегать, если нет какой-либо документированной проблемы с 3.2.x, которая могла бы оправдать обновление.
@Tezra К сожалению, нет. Я не могу заставить даже само приложение постоянно выходить из строя, так что ...
Может быть, у библиотеки клиентской версии Mongo, которую вы сейчас используете, есть проблема? Я подумал, что это локальный экземпляр, и поэтому предложил обновить
@TarunLalwani Да, для разработки я использую локальный экземпляр. И мой локальный экземпляр, и производственный - 3.2.6. Я имею в виду, что если я обновлю свой локальный экземпляр, и тогда все будет работать ... Я все равно не пойму, почему это иногда не удалось раньше, и мне, вероятно, понадобится более хорошее объяснение, чем это, прежде чем я подключу DevOps и другие команды .
Трудно сказать, потому что недавний патч или что-то еще на вашей машине могло повлиять на поведение. Комбинаций может быть много, и они могут быть даже специфичными для вашей машины. Пока ваш коллега не работает в разных средах и не конфигурирует, трудно сказать
@Tezra Как сказано в вопросе и в одном из моих комментариев выше, я подтвердил с помощью пошагового выполнения, что updateBookData выполняется каждый раз, и объект original изменяется до saveing, и вызов save даже возвращается обновленный объект. Но изменения не сохраняются в самой БД. Мне кажется, что это кеширование, но я не знаю ни одной опции кеширования для MongoRepository.
@LuisG. Запустите еще несколько тестов, но добавьте 61-секундный сон между сохранением и возвратом. Если это сработает, то это определенно проблема с промывкой (или проблема с блокировкой).
Не могли бы вы включить ведение журнала уровня отладки для зависимостей Spring mongo и mongodb? Так что при сбое сохранения у вас будет больше информации. Попробуйте logging.level.org.springframework.data.mongodb.core.MongoTemplate=DEBUG logging.level.org.mongodb.driver.protocol.insert=DEBUG logging.level.org.mongodb.driver.protocol.query=DEBUG logging.level.org.mongodb.driver.protocol.command=DEBUG logging.level.org.mongodb.driver.protocol.update=DEBUG в application.properties и сравните логи. Надеюсь, это поможет вам сузить проблему.
журналы типа MongoTemplate : findOne using query: { "_id" : { "$oid" : "somevalue"}} in db.collection: db.somecollection protocol.command: Sending command {find : BsonString{value='somecollection'}} to database [connectionId{localValue:3, serverValue:67}] to server 127.0.0.1:27017 protocol.command: Command completed MongoTemplate: Calling update using query: { "_id" : { "$oid" : "somevalue"} , "version" : 4} and update: update json in collection: some collection protocol.update: Updating in namespace db.somecollection on connection serverValue:67}] protocol.update: Update completed
@Veeram Я обнаружил проблему, см. этот комментарий. Я разрываюсь между тем, чтобы сделать одно из презираемых «Обновлено: Я решил это, это было из-за X» правок, и написать какой-то ответ об уровнях ведения журнала и о том, как определить, перезаписывает ли какой-то другой поток изменения.
Рад, что вы решили эту проблему, но вам следует настроить ведение журнала, чтобы вы могли отлаживать проблему, когда она возникает. Что произойдет, если вы включите ведение журнала на стороне приложения? Он должен записывать журналы, когда другой поток перезаписывает изменения.
@Veeram Обе операции обновления регистрировались как на клиенте JS, так и на сервере Java, но в каждом журнале отображались только «соответствующие» измененные поля, поэтому я не осознавал проблему, пока не поднял уровень журнала БД.
так что решение разоблачить проблему заключалось в том, чтобы поставить условную точку останова, отфильтровав bookId на repository.save(BookData bookData)? : D
@Paizo Я думал, что проблема на стороне MongoDB, поэтому моим решением было поднять уровень verbosity (см. Мой ответ), и именно так я обнаружил два обновления. Если бы я уже подозревал, что «два обновления вместо одного» на стороне Java были основной причиной, тогда я, вероятно, сделал бы, как вы говорите, и действительно проблема всплыла бы, так как я бы видел два вызова save поступающие с разных конечных точек. Взгляд в прошлое - 20/20.
Поскольку этот вопрос решен, вы должны принять ответ, чтобы другие знали, что он решен.
@Tezra Что ж, для меня это действительно решено, но (как вы сами сказали) другие пользователи, которые нашли этот вопрос, могут иметь другую проблему. 11 человек проголосовали за вопрос, но только 2 проголосовали за мой (довольно конкретный) ответ, и только я проголосовал за ваш (хотя я уже понял проблему потока к тому времени, когда вы ее упомянули): возможно, ни один из ответов не достаточно хорош для сообщество? Следовательно, почему вопрос и его награда будут оставаться открытыми до окончания льготного периода, на случай, если кто-то отправит более полный / общий ответ (или улучшит текущий;). Не торопитесь с вещами, которые не нужно торопить.
Вы принимать исходя из того, что помогло вам лично. Вы можете подождать, пока истечет срок награды, но принимайте ее на свой страх и риск, а не сообщества. Другие с подобной проблемой (если она когда-либо существует) могут открыть свой собственный вопрос для этого сценария. : 3
Ответы 2
MongoDB по своей сути является хранилищем кешей, под этим я подразумеваю, что не гарантируется, что его содержимое будет самым последним или обязательно правильным. Мне не удалось найти параметры конфигурации для времени сброса (но они будут настроены в самой БД), но MongoDB добавила функции, чтобы вы могли выбирать быстро + грязно или медленно + очищать. Фактор «свежести», скорее всего, ваша проблема, если вы столкнулись с подобной проблемой. (Даже если вы не используете распределенный, существует разница во времени между подтверждением запроса и подтверждением запроса)
Вот ссылка на сообщение о "чистом чтении" (ключевой момент в следующей цитате)
http://www.dagolden.com/index.php/2633/no-more-dirty-reads-with-mongodb/
I encourage MongoDB users to place themselves (or at least, their application activities) into one of the following groups:
"I want low latency" – Dirty reads are OK as long as things are fast. Use w=1 and read concern 'local'. (These are the default settings.) "I want consistency" – Dirty reads are not OK, even at the cost of latency or slightly out of date data. Use w='majority' and read concern 'majority. use MongoDB v1.2.0;
my $mc = MongoDB->connect( $uri, { read_concern_level => 'majority', w => 'majority', } );
дальнейшее чтение, которое может оказаться полезным, а может и не оказаться
- https://docs.mongodb.com/manual/faq/concurrency/
- https://www.rainforestqa.com/blog/2012-11-05-mongodb-gotchas-and-how-to-avoid-them/ (А именно, раздел Журнал)
Обновлять
Если вы работаете в многопоточной среде, убедитесь, что ваши потоки не попирают чужие обновления. Вы можете проверить, происходит ли это, настроив уровень ведения журнала системы или запроса на 5. https://docs.mongodb.com/manual/reference/log-messages/#log-messages-configure-verbosity
Спасибо за ответы. Я понимаю, что «возможная согласованность» MongoDB может время от времени приводить к некоторым грязным чтениям, когда между операциями всего несколько секунд. Однако я вижу, что изменения никогда сохраняются. Я только что сделал обновление, дождался 15 минут, прежде чем снова запросить БД, и изменений нигде не было видно. Разумеется, 15 минут должно хватить MongoDB для распространения изменений в конфигурации с одним экземпляром без сегментов?
(Кстати, обе нижние ссылки для меня пурпурные, проверял их на прошлой неделе. Вторая была очень интересной, но ничего из того, что там написано, не помогло, так как этот «сброс каждые 60 с, журнал каждые 100 мс», похоже, не соответствует поведению Я вижу. Но все равно спасибо!)
@LuisG. Я полагаю, что для большинства людей, которые задаются этим вопросом, это будет их настоящая проблема. В вашем случае, скорее всего, нет. Конечно, это МОЖЕТ быть много чего. Если это не проблема сброса, выполните сравнение свойств, равных объектам сохранения до публикации, чтобы убедиться, что они одинаковы (т. Е. Идентификатор не изменился или что-то еще), и запустите dbstats перед публикацией (docs.mongodb.com/manual/reference/command/dbStats), чтобы увидеть если НИЧЕГО изменилось в БД. Если вы многопоточны, также возможно, что другой поток попирает ваши изменения.
systemLog.verbosity MongoDB до 3, и после тщательного изучения, это, кажется, реальная проблема. Другой поток обновляет тот же документ всего через 500 мс после моего обновления, но с другими изменениями. Таким образом, мои изменения перезаписываются почти мгновенно, и поэтому я не вижу их ни при следующем вызове findById(), ни при запуске db.bookData.find() в Mongo Shell. Ну что ж.
Однако вопрос о том, почему mongod.log перестал показывать обновления, остается открытым. Может иметь какое-то отношение к slowms в конфигурации журналирования (например, запросы, которые я видел, были медленнее, чем slowms, и это единственная причина, по которой я их вообще видел, по умолчанию не видеть никаких запросов, если verbosity не увеличен).
@LuisG. Конфигурация журнала по умолчанию: 100 + мс - это «медленный» запрос, и регистратор будет регистрировать только «медленные» запросы. (здесь объясняется docs.mongodb.com/manual/reference/method/db.setProfilingLeve l) Чтобы регистрировать все запросы, вам нужно изменить logLevel с 0 (мин.) на 5 (макс.) (docs.mongodb.com/manual/reference/log-messages/… (Установить подробность запроса)). Если вы не изменили настройки по умолчанию, это то, что вы видите.
Да. Два обещания от клиента JS вызывали две разные конечные точки из серверной части Java, которые, в свою очередь, одновременно создавали два findById. Затем каждый внес свои собственные модификации и назвал save последним, который сделал это, фактически заменив первый.
@LuisG. Хорошо. ^ _ ^ Я обновил ответ, включив в него аргументы в пользу многопоточной безопасности для будущих читателей, чтобы им не приходилось копаться в комментариях, и поскольку это был фактический ответ на ваш вопрос. Рад, что смог помочь. : 3
Проблема решена. Другой асинхронный вызов от клиента JS к другой конечной точке в бэкэнде Java перезаписывал мой обновленный документ в другом потоке с исходными значениями.
Обе операции обновления вызывали findById перед сохранением. Проблема заключалась в том, что они делали это одновременно, поэтому получали одинаковые исходные значения.
Затем каждый продолжил обновление своих соответствующих полей и в конце вызвал save, в результате чего другой поток фактически переопределил мои изменения.
Каждый вызов регистрировался только с соответствующими измененными полями, поэтому я не осознавал, что одно из них перезаписывало изменения другого.
После того, как я добавил systemLog.verbosity: 3 в config.cfg MongoDB, чтобы он регистрировал операции все, стало ясно, что одновременно выполнялись 2 разные операции WRITE (с интервалом ~ 500 мс), но с разными значениями.
Затем оставалось просто переместить findById ближе к save и обеспечить выполнение JS-вызовов по порядку (сделав одно из обещаний зависимым от другого).
Оглядываясь назад, этого, вероятно, не произошло бы, если бы я использовал MongoOperations или MongoTemplate, которые предлагают одиночные методы update и findAndModify, которые также допускают операции с одним полем, вместо MongoRepository, где я вынужден делать это в 3 этапа (find, изменить возвращенный объект, save) и работать с полным документом.
Обновлено: Мне не очень понравился мой первый подход «переместить findById ближе к save», поэтому в конце концов я сделал то, что считал правильным, и реализованы пользовательские методы сохранения, которые использовали более детальный MongoTemplate API update. Окончательный код:
/* MongoRepository provides entity-based default Spring Data methods */
/* BookDataRepositoryCustom provides field-level update methods */
public interface BookDataRepository extends MongoRepository<BookData, String>, BookDataRepositoryCustom {
BookData findById(String id);
}
/* Interface for the custom methods */
public interface BookDataRepositoryCustom {
int saveCurrentPage(String id, Integer currentPage);
}
/* Custom implementation using MongoTemplate. */
@SuppressWarnings("unused")
public class BookDataRepositoryImpl implements BookDataRepositoryCustom {
@Inject
MongoTemplate mongoTemplate;
@Override
public int saveCurrentPage(String id, Integer currentPage) {
Query query = new Query(Criteria.where("_id").is(id));
Update update = new Update();
update.set("currentPage", currentPage);
WriteResult result = mongoTemplate.updateFirst(query, update, BookData.class);
return result == null ? 0 : result.getN();
}
}
// Old code: get entity from DB, update, save. 3 steps with plenty of room for interferences.
// BookData bookData = bookDataRepository.findById(bookDataId);
// bookData.setCurrentPage(currentPage);
// bookDataRepository.save(bookData);
// New code: update single field. 1 step, 0 problems.
bookDataRepository.saveCurrentPage(bookDataId, currentPage);
Таким образом, каждая конечная точка может передавать update через MongoTemplate так часто, как это необходимо, не беспокоясь о перезаписи несвязанных полей, и я по-прежнему сохраняю методы MongoRepository на основе сущностей для таких вещей, как создание новых сущностей, методы findBy, аннотированные @Query и т. д.
Вы также можете использовать оптимистическую блокировку (см. docs.spring.io/spring-data/mongodb/docs/current/reference/ht ml /…), чтобы предотвратить эти постоянные обновления. По сути, вам нужно добавить поле «версия» типа long в свой объект BookData, аннотированное @Version, а Spring Data позаботится обо всем остальном за вас!
[1] На самом деле
Get-content mongod.log -Tail 10 -Waitв PowerShell, но не совсем актуальный.