SASGIS - SAS.Планета
View Issue Details
IDProjectCategoryView StatusDate SubmittedLast Update
0002016SAS.Планета[All Projects] Багpublic15-07-2013 06:5702-08-2013 12:02
ReporterGarl 
Assigned Tozed 
PrioritynormalSeverityminorReproducibilityhave not tried
StatusresolvedResolutionfixed 
PlatformWindowsOS7OS VersionHome Premium
Product Version.Nightly 
Target Version131111Fixed in Version131111 
Summary0002016: Обработка ошибок в BerkeleyDB
Descriptionесть подозрения на битый кэш, но вдруг нет.
Steps To Reproduce
Additional Information
TagsNo tags attached.
Relationships
Attached Files? SASPlanet.Debug.elf (76,163) 15-07-2013 06:57
http://www.sasgis.org/mantis/file_download.php?file_id=1434&type=bug
? 16-07-2013-SASPlanet.Debug.elf (71,859) 16-07-2013 08:39
http://www.sasgis.org/mantis/file_download.php?file_id=1437&type=bug
Issue History
Date ModifiedUsernameFieldChange
15-07-2013 06:57GarlNew Issue
15-07-2013 06:57GarlFile Added: SASPlanet.Debug.elf
15-07-2013 12:01zedNote Added: 0012070
15-07-2013 12:33zedNote Added: 0012071
15-07-2013 13:22GarlNote Added: 0012072
15-07-2013 13:36zedNote Added: 0012073
15-07-2013 13:44vasketsovNote Added: 0012074
15-07-2013 14:05zedNote Added: 0012075
15-07-2013 14:12vasketsovNote Added: 0012076
15-07-2013 14:17vasketsovNote Added: 0012077
15-07-2013 14:25zedNote Added: 0012078
15-07-2013 14:37vasketsovNote Added: 0012079
15-07-2013 14:38vasketsovNote Added: 0012080
15-07-2013 14:43zedNote Added: 0012081
15-07-2013 14:46zedNote Added: 0012082
15-07-2013 18:21vasketsovNote Added: 0012090
16-07-2013 04:55zedNote Added: 0012092
16-07-2013 05:20zedNote Added: 0012096
16-07-2013 05:45zedAssigned To => zed
16-07-2013 05:45zedStatusnew => confirmed
16-07-2013 05:45zedTarget Version => 131111
16-07-2013 05:45zedSummaryBerkley DB Unknown error message => Обработка ошибок в BerkeleyDB
16-07-2013 07:28vasketsovNote Added: 0012103
16-07-2013 08:38GarlNote Added: 0012104
16-07-2013 08:39GarlFile Added: 16-07-2013-SASPlanet.Debug.elf
16-07-2013 08:39GarlNote Edited: 0012104bug_revision_view_page.php?rev_id=5566
16-07-2013 08:40GarlFile Added: dbv_conv.jpg
16-07-2013 08:40GarlFile Added: dbv_conv_2.jpg
16-07-2013 08:41GarlNote Edited: 0012104bug_revision_view_page.php?rev_id=5567
16-07-2013 08:44GarlNote Added: 0012105
16-07-2013 08:47GarlNote Added: 0012106
16-07-2013 08:47GarlFile Added: 12-43-SASPlanet.Debug.elf
16-07-2013 08:47GarlNote Edited: 0012106bug_revision_view_page.php?rev_id=5569
16-07-2013 11:53zedNote Deleted: 0012104
16-07-2013 11:54zedNote Deleted: 0012105
16-07-2013 11:54zedFile Deleted: dbv_conv.jpg
16-07-2013 11:54zedFile Deleted: dbv_conv_2.jpg
16-07-2013 12:04zedNote Deleted: 0012106
16-07-2013 12:04zedFile Deleted: 12-43-SASPlanet.Debug.elf
16-07-2013 12:13zedNote Added: 0012107
17-07-2013 09:51vasketsovNote Added: 0012109
02-08-2013 12:02zedStatusconfirmed => resolved
02-08-2013 12:02zedFixed in Version => 131111
02-08-2013 12:02zedResolutionopen => fixed

Notes
(0012070)
zed   
15-07-2013 12:01   
Какой-то странный стек вызовов. Вначале шла вполне прослеживаемая запись тайла в хранилище, а потом вдруг откуда ни возьмись оно вылетает в TBerkeleyDBValue.Assign.

А в sdb.log ничего не записалось? Там ещё есть подозрительный вызов функции __db_errx из libdb51.dll, т.е. скорее всего ошибка прилетела оттуда, но почему-то выстрелило чёрт-знает куда. Возможно как раз из-за переделанной обработки ошибок.
(0012071)
zed   
15-07-2013 12:33   
>Возможно как раз из-за переделанной обработки ошибок.
Да, всё больше склоняюсь к этому мнению. Если библиотека сообщает нам об ошибке внутри себя, она возвращает код ошибки и сообщение, т.е. по сути, исключения как такового ещё и нету. А мы вдруг просим эврику показать нам последнее исключение. Вот оно и показывает абы что.
(0012072)
Garl   
15-07-2013 13:22   
15-07-2013 10:47:18.798 Error [BerkeleyDB Value]: Bad magic value (ZVAL)
15-07-2013 10:54:36.103 Error [BerkeleyDB Value]: Bad CRC32 value: 0xA7B1EFD0
15-07-2013 10:54:38.204 Error [BerkeleyDB Value]: Bad CRC32 value: 0x1F8644D6
15-07-2013 10:54:55.807 BerkeleyDB: z14\4\2\19.11.sdbv page 6868 is on free list with type 7 e:\cache_dbv\sat_all_v1\
15-07-2013 11:01:11.031 Error [BerkeleyDB Value]: Bad magic value (▐6Yг)
15-07-2013 11:01:11.073 Error [BerkeleyDB Value]: Bad CRC32 value: 0x1CB62836
15-07-2013 11:01:51.595 BerkeleyDB: z17\39\23\156.93.sdbv page 186094 is on free list with type 7 e:\cache_dbv\sat_all_v1\
(0012073)
zed   
15-07-2013 13:36   
Ну вот и ошибки:
BerkeleyDB: z14\4\2\19.11.sdbv page 6868 is on free list with type 7 e:\cache_dbv\sat_all_v1\
BerkeleyDB: z17\39\23\156.93.sdbv page 186094 is on free list with type 7 e:\cache_dbv\sat_all_v1\

Так что это на 100% битый кэш. К тому же, ещё и с мусором, судя по сообщениям: Bad CRC32 value и Bad magic value

Но пока остаётся открытым вопрос, почему эврика не ловит все эти ошибки, что прилетают от либы и пишутся в лог. Возможно стоит переименовать тикет и посвятить его обработке ошибок Эврикой.
(0012074)
vasketsov   
15-07-2013 13:44   
>исключения как такового ещё и нету. А мы вдруг просим эврику показать
Если это про EBerkeleyDBEureka.Create, то это можно полечить добавлением проверки типа
if (ExceptObject <> nil) and not (ExceptObject is EAbort) then
вокруг
ShowLastExceptionData.

Это исключит вызов запуска эврики вне фрейма текущего исключения.
(0012075)
zed   
15-07-2013 14:05   
>if (ExceptObject <> nil)
Так в противном случае и эврика ничего не должна показать. Даже без этой проверки.

У нас ситуация такая:
15-07-2013 11:01:11.073 Error [BerkeleyDB Value]: Bad CRC32 value: 0x1CB62836
15-07-2013 11:01:51.595 BerkeleyDB: z17\39\23\156.93.sdbv page 186094 is on free list with type 7 e:\cache_dbv\sat_all_v1\

т.е. вначале был нармальный эксепшен в САС, который Эврика не словила, затем прилетела ошибка из библиотеки, в результате чего создалось исключение EBerkeleyDBEureka и показало на предыдущий эксепшен (Bad CRC32 value).
(0012076)
vasketsov   
15-07-2013 14:12   
>в противном случае и эврика ничего не должна показать
Что-то мне не удалось найти, что помешает вызвать ExceptNotify.
Стек-то развернуть дело нехитрое.
А проверка там вида
if ((not Initialized) or (IsAParent(Obj, EAbort))) then
  Exit;
(0012077)
vasketsov   
15-07-2013 14:17   
raise EBerkeleyDBExeption.Create(EMsg);
except
  ShowLastExceptionData;

Хм. Знаешь, что будет в эврике при исключении в конструкторе EBerkeleyDBExeption (например при нехватке памяти)?
(0012078)
zed   
15-07-2013 14:25   
Не знаю. А ты знаешь как ещё нормально сгенерировать исключение, чтобы оно попало в Эврику? В твоём случае, при ошибке в либе вида BerkeleyDB: z17\39\23\156.93.sdbv page 186094 is on free list with type 7 e:\cache_dbv\sat_all_v1\ Эврика всё равно промолчит.
(0012079)
vasketsov   
15-07-2013 14:37   
>знаешь как ещё нормально сгенерировать исключение
Не знаю (((
(0012080)
vasketsov   
15-07-2013 14:38   
Но меня напрягает, что строка с BerkeleyDB:выглядит не как строка исключения.
(0012081)
zed   
15-07-2013 14:43   
Ну так это и не исключение, а простое сообщение. "BerkeleyDB" это Error Prefix, который подсказывает, что ошибка в файле БД. Задаётся вручную в коде. Там ещё есть и "BerkeleyDB Env" - будет отсвечивать при ошибках в энвайронминте.
(0012082)
zed   
15-07-2013 14:46   
К примеру есть такая ситуация:

15-07-2013 16:07:19.302 BerkeleyDB: file z8\0\0\0.0.sdbv has LSN 42/1241061, past end of log at 1/28 d:\coding\delphi\src\sas.planet\sas.planet.src\.bin\cache_dbv\sat\
15-07-2013 16:07:19.304 EBerkeleyDBExeption: BerkeleyDB: file z8\0\0\0.0.sdbv has LSN 42/1241061, past end of log at 1/28 d:\coding\delphi\src\sas.planet\sas.planet.src\.bin\cache_dbv\sat\
15-07-2013 16:07:19.307 EBerkeleyDBExeption: EBerkeleyDBExeption: BerkeleyDB: file z8\0\0\0.0.sdbv has LSN 42/1241061, past end of log at 1/28 d:\coding\delphi\src\sas.planet\sas.planet.src\.bin\cache_dbv\sat\
15-07-2013 16:07:19.310 EAssertionFailed: Assertion failure (D:\coding\Delphi\src\SAS.Planet\sas.planet.src\TileStorage\BerkeleyDB\u_BerkeleyDBPool.pas, line 187)

Эврика сообщила только про ассерт :(

Причём, меня ешё напрягает, что там один эксепшен словило 2 раза (3-я строка).
(0012090)
vasketsov   
15-07-2013 18:21   
>так это и не исключение, а простое сообщение
А зачем ты тогда хочешь его в эврику пропихнуть? И как?

>меня ешё напрягает, что там один эксепшен словило 2 раза
Это просто reraise в стеке, как раз никаких проблем с этим нет.
(0012092)
zed   
16-07-2013 04:55   
>>так это и не исключение, а простое сообщение
>А зачем ты тогда хочешь его в эврику пропихнуть? И как?
Нужно сгенерировать исключение с этим сообщением, чтобы Эврика выкинула юзеру своё окошко и показало ошибку. После таких ошибок кэш уже всё-равно не рабочий и все манипуляции с ним из САСа нужно аварийно завершать. Сейчас же, это сообщение быстро мелькает на тайлах, изображение "застывает", и выкидывается EAssertionFailed. После этого юзер приходит в багтрекер с этим или подобным ассертом, с уверенностью, что проблема в САС, хотя на самом деле проблема в кэше и первое сообщение об этом чётко говорит.
(0012096)
zed   
16-07-2013 05:20   
О, похоже мои вчерашние изменения не прошли даром. В тикете 0002018 лежит elf сгенерированный из-за аналогичной ошибки, но там уже верный стек и юзер увидел правильное сообщение.
(0012103)
vasketsov   
16-07-2013 07:28   
>После таких ошибок кэш уже всё-равно не рабочий
Почему? Это какая-то нештатная ошибка?
Например, в БД нарушение первичного ключа (xyzv) или даже если просто текст запроса неверно написать, не приводит к порче данных и падению базы.
А тут почему? Из-за одновременного доступа из разных потоков или процессов?
(0012107)
zed   
16-07-2013 12:13   
Тут если БД ругается через вызов CallBack функции, означает фатальную ошибку. Для других ошибок, не фатальных, у функций read/write и прочих предусмотрен код возврата.

>А тут почему? Из-за одновременного доступа из разных потоков или процессов?
Где именно "тут"? В приведенном выше сообщении я специально удалил папку env на тестовом кэше, чтобы оно ругнулось. Проблемы Garl с "page 186094 is on free list with type 7" пока не ясно из-за чего. Многопоточность тут по-идее никак не должна влиять, бо я там засинхронизировал все вызовы по самое ни хочу.
(0012109)
vasketsov   
17-07-2013 09:51   
>вызов CallBack функции, означает фатальную ошибку
Понял.