Пролог
В предыдущем посте я описал, на какие грабли пришлось наступить, чтобы заставить Sequoia создавать таблицы в RecoveryLog и запускать backends. Тем не менее, сама работа контроллера по-прежнему оставалась некорректной, и, как выяснилось, без правки исходников решить проблему никак не получалось.
Ковыряем исходники
Исходники Sequoia точно так же, как дистрибутив и документация, доступны на официальном сайте. После разархивации объём исходников меня разочаровал, я ожидал от подобной супер-системы большего числа файлов. Но не в количестве файлов суть.
Ещё раз поглядев на генерируемое исключение, я дополз до проблемного кода в файле src/org/continuent/sequoia/controller/recoverylog/events/LogRequestEvent.java. Вот он:
public void execute(LoggerThread loggerThread, RecoveryLogConnectionManager manager) { Trace logger = loggerThread.getLogger(); try { if (logger.isDebugEnabled()) logger.debug(Translate.get("recovery.jdbc.loggerthread.log.info", logEntry.getLogId())); PreparedStatement pstmt = manager.getLogPreparedStatement(); pstmt.setLong(RecoveryLog.COLUMN_INDEX_LOG_ID, logEntry.getLogId()); pstmt.setString(RecoveryLog.COLUMN_INDEX_VLOGIN, logEntry.getLogin()); pstmt.setString(RecoveryLog.COLUMN_INDEX_SQL, logEntry.getQuery()); pstmt.setString(RecoveryLog.COLUMN_INDEX_SQL_PARAMS, logEntry .getQueryParams()); pstmt.setString(RecoveryLog.COLUMN_INDEX_AUTO_CONN_TRAN, logEntry .getAutoConnTrans()); pstmt.setLong(RecoveryLog.COLUMN_INDEX_TRANSACTION_ID, logEntry.getTid()); pstmt.setLong(RecoveryLog.COLUMN_INDEX_REQUEST_ID, logEntry .getRequestId()); pstmt.setString(RecoveryLog.COLUMN_INDEX_EXEC_STATUS, logEntry .getExecutionStatus()); pstmt.setLong(RecoveryLog.COLUMN_INDEX_EXEC_TIME, logEntry .getExecutionTimeInMs()); pstmt.setLong(RecoveryLog.COLUMN_INDEX_UPDATE_COUNT, logEntry .getUpdateCountResult()); if (logger.isDebugEnabled()) logger.debug(pstmt.toString()); try { pstmt.setEscapeProcessing(logEntry.getEscapeProcessing()); } catch (Exception ignore) { } // Здесь бросается исключение: int updatedRows = pstmt.executeUpdate(); if ((updatedRows != 1) && logger.isWarnEnabled()) logger .warn("Recovery log did not update a single entry while executing: " + pstmt.toString()); } catch (SQLException e) { manager.invalidate(); if ("T".equals(logEntry.getAutoConnTrans())) logger.error(Translate.get( "recovery.jdbc.loggerthread.log.failed.transaction", new String[]{ logEntry.getQuery(), String.valueOf(logEntry.getTid())}), e); else logger.error(Translate.get("recovery.jdbc.loggerthread.log.failed", logEntry.getQuery()), e); // Push object back in the queue, it needs to be logged again loggerThread.putBackAtHeadOfQueue(this, e); } }
От этого кода я и стал плясать, в результате чего всё-таки смог найти место, где можно выплюнуть создаваемое SQL-выражение. Дело осталось за небольшим — скомпилить исходники.
Сборка Sequoia
Сборка, в принципе, несложна и выполняется через Ant. Но предварительно следовало сконфигурировать файл build.properties, в котором я прописал версию используемой JDK — 1.5:
javac.target = 1.5 javac.source = 1.5
После этого, немного поизучав build.xml, я запустил в shell следующую команду:
ant clean && ant jar
Исходники собрались (правда, с ворнингами, ARGH!!!), и у меня на руках уже были новые JAR, которые я и подпихнул взамен штатных.
Патчинг
После перезапуска контроллера пропатченный код выплюнул в лог SQL-выражения, используемые для вставки/обновления данных RecoveryLog:
2009-08-26 19:17:25,368 DEBUG sequoia.controller.recoverylog Insert statement: INSERT INTO T_RECOVERY VALUES(?,?,?,?,?,?,?,?,?,?) 2009-08-26 19:17:25,372 DEBUG sequoia.controller.recoverylog Update statement: UPDATE T_RECOVERY SET exec_status=?,update_count=?,exec_time=? WHERE log_id=?
Синтаксис INSERT-выражения меня просто убил, так как в нём не учтено, что поля могут поменяться местами. Потратив час на модификацию кода, я, в конце-концов, пропатчил создаваемые SQL-выражения, а также добавил отладочную инфу к проблемной функции в файле src/org/continuent/sequoia/controller/recoverylog/events/LogRequestEvent.java:
public void execute(LoggerThread loggerThread, RecoveryLogConnectionManager manager) { Trace logger = loggerThread.getLogger(); try { if (logger.isDebugEnabled()) logger.debug(Translate.get("recovery.jdbc.loggerthread.log.info", logEntry.getLogId())); PreparedStatement pstmt = manager.getLogPreparedStatement(); pstmt.setLong(RecoveryLog.COLUMN_INDEX_LOG_ID, logEntry.getLogId()); if (logger.isDebugEnabled()) logger.debug("logID = " + logEntry.getLogId()); pstmt.setString(RecoveryLog.COLUMN_INDEX_VLOGIN, logEntry.getLogin()); if (logger.isDebugEnabled()) logger.debug("login = " + logEntry.getLogin()); pstmt.setString(RecoveryLog.COLUMN_INDEX_SQL, logEntry.getQuery()); if (logger.isDebugEnabled()) logger.debug("query = " + logEntry.getQuery()); pstmt.setString(RecoveryLog.COLUMN_INDEX_SQL_PARAMS, logEntry .getQueryParams()); if (logger.isDebugEnabled()) logger.debug("queryParams = " + logEntry.getQueryParams()); pstmt.setString(RecoveryLog.COLUMN_INDEX_AUTO_CONN_TRAN, logEntry .getAutoConnTrans()); if (logger.isDebugEnabled()) logger.debug("autoConnTrans = " + logEntry.getAutoConnTrans()); pstmt.setLong(RecoveryLog.COLUMN_INDEX_TRANSACTION_ID, logEntry.getTid()); if (logger.isDebugEnabled()) logger.debug("transactionID = " + logEntry.getTid()); pstmt.setLong(RecoveryLog.COLUMN_INDEX_REQUEST_ID, logEntry .getRequestId()); if (logger.isDebugEnabled()) logger.debug("RequestID = " + logEntry.getRequestId()); pstmt.setString(RecoveryLog.COLUMN_INDEX_EXEC_STATUS, logEntry .getExecutionStatus()); if (logger.isDebugEnabled()) logger.debug("executionStatus = " + logEntry.getExecutionStatus()); pstmt.setLong(RecoveryLog.COLUMN_INDEX_EXEC_TIME, logEntry .getExecutionTimeInMs()); if (logger.isDebugEnabled()) logger.debug("executionTimeMs = " + logEntry.getExecutionTimeInMs()); pstmt.setLong(RecoveryLog.COLUMN_INDEX_UPDATE_COUNT, logEntry .getUpdateCountResult()); if (logger.isDebugEnabled()) logger.debug("updateCount = " + logEntry.getUpdateCountResult()); if (logger.isDebugEnabled()) logger.debug(pstmt.toString()); try { pstmt.setEscapeProcessing(logEntry.getEscapeProcessing()); } catch (Exception ignore) { } int updatedRows = pstmt.executeUpdate(); if ((updatedRows != 1) && logger.isWarnEnabled()) logger .warn("Recovery log did not update a single entry while executing: " + pstmt.toString()); } catch (SQLException e) { manager.invalidate(); if ("T".equals(logEntry.getAutoConnTrans())) logger.error(Translate.get( "recovery.jdbc.loggerthread.log.failed.transaction", new String[]{ logEntry.getQuery(), String.valueOf(logEntry.getTid())}), e); else logger.error(Translate.get("recovery.jdbc.loggerthread.log.failed", logEntry.getQuery()), e); // Push object back in the queue, it needs to be logged again loggerThread.putBackAtHeadOfQueue(this, e); } }
Ряд исключений сразу исчез. Тем не менее, остались ещё проблемы, которые были исправлены только за счёт комментирования этих строчек кода:
/* try { pstmt.setEscapeProcessing(logEntry.getEscapeProcessing()); } catch (Exception ignore) { }*/
Только после этого и очередной, N-надцатой пересборки пакетов перезапускаемый контроллер перестал ругаться на вставку и выборку данных при прогонке теста. Краш тест?
Краш-тест (leightweight version)
В качестве leightweight-теста я решил воспользоваться Sequoia Console и вырубить второй backend:
CJDBC(admin) > disable oracle02 Disabling backend oracle02 with automatic checkpoint.
Прогнав тест, я убедился, что в первую базу запись была вставлена, а в отключенную — нет. При чём, содержимое Recovery Log пополнилось записями:
LOG_ID VLOGIN SQL_QUERY SQL_QUERY_PARAM AUTO_CONN_TRAN TRANSACTION_ID REQUEST_ID EXEC_STATUS EXEC_TIME UPDATE_COUNT ---------------------- ---------------------------------------------------------------- -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- -------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- -------------- ---------------------- ---------------------- ----------- ---------------------- ---------------------- 1 user begin T 0 0 S 0 -1 2 user INSERT INTO Tm_First (nID, strMessage, nCode) VALUES (?, ?, ?) T 0 0 S 118 1 3 user commit T 0 0 S 0 0 4 user rollback T 1 0 S 0 0
Что ж, впечатляет! Попробуем заново поднять backend:
CJDBC(admin) > enable oracle02 Enabling backend oracle02 from its last known checkpoint
После некоторых раздумий и логописательств, контроллер-таки остановился, и я убедился, что недостающая запись во второй базе появилась. Только это никак не ура, возвращаемся к краш-тестам.
Краш-тест (hardcore version)
Что ж, этот краш-тест, как и в предыдущих случаях, заключался в блокировке пользователя и обрубании коннекций с последующим запуском теста.
Что же в результате? В RecoveryLog появилась запись о вставке, и в первый backend запись была вставлена. Я, было, обрадовался такому положению дел и разлочил пользовательскую учётку, что не вызвало никакой реакции со стороны контроллера. Последующие запуски теста не накладывали никаких отпечатков на вторую доступную базу.
Тогда я решил перезапустить backend через консоль:
CJDBC(admin) > disable oracle02 Disabling backend oracle02 with automatic checkpoint. CJDBC(admin) > enable oracle02 Enabling backend oracle02 from its last known checkpoint Cannot enable backend oracle02 from a known state. Resynchronize this backend by restoring a dump.
Оппаньки! Это, значит, после временной потери коннекта я должен восстанавливать базу из бэкапа? Что за бред!!!
В поисках лекарства решил заглянуть в Administration Guide, но там нашёл инфу только про дампы.
Резюме
Фу и фи. Чем больше ковыряюсь в этой софтине, тем больше убеждаюсь в её реальной непродуманности и ненадёжности. Может быть, я чего-то упускаю, но за эти четыре дня у меня уже порой лезут глаза на лоб от её выходок. Больше всего поражают танцы с бубном вокруг, казалось бы, простых вещей. В общем, завтра ещё поковыряюсь с ней, может всё-таки докопаюсь до истины.
