Closed EugeneYushin closed 6 years ago
@eselyavka @turu Guys, can you please check this PR?
@EugeneYushin can you please reflect those changes in README.MD
too, please, all other looks good to me. Going to test those changes in my sandbox env and merge in case of success.
@eselyavka I've update pom file with new version 1.2 to allow clients to choose the one which fits them better, as well as added notes in README.
@EugeneYushin test this in my sandbox env with CDH-5.12.0
. Seems this bug is still actual - https://liquibase.jira.com/browse/CORE-3220 in version 3.6.2 thus let's keep previous stable version.
[vagrant@quickstart examples]$ ~/liquibase --logLevel=debug update
Starting Liquibase at Sun, 30 Sep 2018 16:29:24 PDT (version 3.6.2 built at 2018-07-03 11:28:09)
Liquibase: Update has been successful.
Going to check 3.5.2
with new hive/impala drivers.
Attaching results of the integration test with liquibase version 3.5.2
integration_tests_hive_impala.log.gz - SUCCESS
Besides that pls find my patch to rollback to version 3.5.2
patch.diff.gz
@eselyavka / @eseliavka-ias (not sure which one is up to date xD) Starting with liqui 3.6+, they have exposed SLF4J as a logging framework. Unfortunately, after a short play I didn't manage to plug logging in (not sure why logback/log4 properties files doesn't help much). Let me spend some more time on this.
Moreover, I found that UPDATE logic doesn't work with impala table. E.g. plugin throws when trying to update md5 hashes cause' Impala tables are hdfs files and doesn't support updates (only Kudu storage does). But this is another topic to discuss. Just fyi.
Can you give it a shot with valid logback config file? E.g.:
# cat lib/logback.xml
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>
<appender name="FILE" class="ch.qos.logback.core.FileAppender">
<file>/tmp/testFile.log</file>
<append>false</append>
<immediateFlush>true</immediateFlush>
<encoder>
<pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
</encoder>
</appender>
<root level="debug">
<appender-ref ref="FILE" />
</root>
<logger name="liquibase.ext">
<level value="DEBUG" />
<appender-ref ref="FILE" />
</logger>
</configuration>
Results in:
# cat /tmp/testFile.log
11:56:24.373 [main] INFO l.integration.commandline.Main - Starting Liquibase at Mon, 01 Oct 2018 11:56:24 UTC (version 3.6.2 built at 2018-07-03 11:28:09)
11:56:25.568 [main] INFO l.servicelocator.ServiceLocator - Can not use class liquibase.ext.metastore.database.HiveMetastoreDatabase as a Liquibase service because it does not have a no-argument constructor
11:56:26.300 [main] DEBUG l.e.m.impala.database.ImpalaDatabase - Connected to User@jdbc:impala://ip-172-31-19-142.ec2.internal:21050/tmp;AuthMech=3;UID=dwh-user;PWD=DK46bFV$Vw1cx%mX2hjM+NPH6fYu;SSL=1;AllowSelfSignedCerts=1;transportMode=sasl
11:56:26.300 [main] DEBUG l.e.m.impala.database.ImpalaDatabase - Connected to User@jdbc:impala://ip-172-31-19-142.ec2.internal:21050/tmp;AuthMech=3;UID=dwh-user;PWD=DK46bFV$Vw1cx%mX2hjM+NPH6fYu;SSL=1;AllowSelfSignedCerts=1;transportMode=sasl
11:56:26.300 [main] DEBUG l.e.m.impala.database.ImpalaDatabase - Not adjusting the auto commit mode; it is already true
11:56:26.300 [main] DEBUG l.e.m.impala.database.ImpalaDatabase - Not adjusting the auto commit mode; it is already true
11:56:27.297 [main] INFO l.e.m.database.HiveMetastoreDatabase - Schema name is 'tmp'
11:56:27.297 [main] INFO l.e.m.database.HiveMetastoreDatabase - Schema name is 'tmp'
11:56:28.158 [main] INFO l.e.m.l.MetastoreLockService - Looking for table 'DATABASECHANGELOGLOCK'
11:56:28.158 [main] INFO l.e.m.l.MetastoreLockService - Looking for table 'DATABASECHANGELOGLOCK'
11:56:28.407 [main] INFO liquibase.executor.jvm.JdbcExecutor - SELECT COUNT(*) FROM tmp.DATABASECHANGELOGLOCK
11:56:28.483 [main] INFO liquibase.executor.jvm.JdbcExecutor - SELECT LOCKED FROM tmp.DATABASECHANGELOGLOCK WHERE ID=1
11:56:28.682 [main] INFO liquibase.executor.jvm.JdbcExecutor - SET SYNC_DDL=1
11:56:28.687 [main] INFO liquibase.executor.jvm.JdbcExecutor - TRUNCATE TABLE tmp.DATABASECHANGELOGLOCK
11:56:35.439 [main] INFO liquibase.executor.jvm.JdbcExecutor - INSERT INTO tmp.DATABASECHANGELOGLOCK (ID, LOCKED, LOCKEDBY, LOCKGRANTED) VALUES (1, TRUE, 'ip-172-31-19-60.ec2.internal [172.31.19.60]', '2018-10-01 11:56:28')
11:56:43.447 [main] INFO liquibase.executor.jvm.JdbcExecutor - SET SYNC_DDL=0
11:56:43.451 [main] INFO l.e.m.l.MetastoreLockService - Change log lock has been successfully acquired
11:56:43.451 [main] INFO l.e.m.l.MetastoreLockService - Change log lock has been successfully acquired
11:56:44.498 [main] INFO liquibase.executor.jvm.JdbcExecutor - SELECT MD5SUM FROM tmp.DATABASECHANGELOG WHERE MD5SUM IS NOT NULL
11:56:44.575 [main] INFO liquibase.executor.jvm.JdbcExecutor - SELECT COUNT(*) FROM tmp.DATABASECHANGELOG
11:56:44.640 [main] INFO l.c.StandardChangeLogHistoryService - Reading from tmp.DATABASECHANGELOG
11:56:44.640 [main] INFO liquibase.executor.jvm.JdbcExecutor - SELECT * FROM tmp.DATABASECHANGELOG ORDER BY DATEEXECUTED ASC, ORDEREXECUTED ASC
11:56:45.734 [main] INFO l.e.m.l.MetastoreLockService - Looking for table 'DATABASECHANGELOGLOCK'
11:56:45.734 [main] INFO l.e.m.l.MetastoreLockService - Looking for table 'DATABASECHANGELOGLOCK'
11:56:46.753 [main] INFO l.e.m.l.MetastoreLockService - Looking for table 'DATABASECHANGELOGLOCK'
11:56:46.753 [main] INFO l.e.m.l.MetastoreLockService - Looking for table 'DATABASECHANGELOGLOCK'
11:56:46.858 [main] INFO liquibase.executor.jvm.JdbcExecutor - SET SYNC_DDL=1
11:56:46.862 [main] INFO liquibase.executor.jvm.JdbcExecutor - TRUNCATE TABLE tmp.DATABASECHANGELOGLOCK
11:56:53.445 [main] INFO liquibase.executor.jvm.JdbcExecutor - INSERT INTO tmp.DATABASECHANGELOGLOCK (ID, LOCKED) VALUES (1, FALSE)
11:57:01.453 [main] INFO liquibase.executor.jvm.JdbcExecutor - SET SYNC_DDL=0
11:57:01.457 [main] INFO l.e.m.l.MetastoreLockService - Change log lock has been successfully released
11:57:01.457 [main] INFO l.e.m.l.MetastoreLockService - Change log lock has been successfully released
11:57:01.458 [main] INFO l.integration.commandline.Main - Liquibase: Update has been successful.
@EugeneYushin it's much better right now, but console appender still not working
[vagrant@quickstart examples]$ tail ~/lib/logback.xml && ~/liquibase update
<root level="debug">
<appender-ref ref="STDOUT" />
</root>
<logger name="liquibase.ext">
<level value="DEBUG" />
<appender-ref ref="STDOUT" />
</logger>
</configuration>
07:36:00,866 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
07:36:00,866 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
07:36:00,867 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/home/vagrant/lib/logback.xml]
07:36:01,015 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
07:36:01,021 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
07:36:01,032 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
07:36:01,101 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to DEBUG
07:36:01,102 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
07:36:01,104 |-INFO in ch.qos.logback.classic.joran.action.LevelAction - liquibase.ext level set to DEBUG
07:36:01,104 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[liquibase.ext]
07:36:01,104 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
07:36:01,106 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@d40869 - Registering current configuration as safe fallback point
Starting Liquibase at Mon, 01 Oct 2018 07:36:01 PDT (version 3.6.2 built at 2018-07-03 11:28:09)
Liquibase: Update has been successful.
That's because liqui developers decided to wreck everybody's legs with theirs logging approach.
They use sl4j markers to filter out all non LogType.USER_MESSAGE
tags https://github.com/liquibase/liquibase/blob/bce767333bd4867708a03ca5fb90df868433fb44/liquibase-core/src/main/java/liquibase/logging/LogType.java#L11
https://github.com/liquibase/liquibase/blob/bce767333bd4867708a03ca5fb90df868433fb44/liquibase-core/src/main/java/liquibase/integration/commandline/Main.java#L241
https://github.com/liquibase/liquibase/blob/bce767333bd4867708a03ca5fb90df868433fb44/liquibase-core/src/main/java/liquibase/integration/commandline/Main.java#L1530
And we need to specify logger.info(LogType.USER_MESSAGE, '....')
if we want to pass anything to Console.
To setup Debug level for liqui CLI tool (not our plugin), you can set property -Dliquibase.defaultlogger.level=debug
.
Please, let me know your thoughts. We can proceed with downgrading liqui ver to 3.5.2, or use 3.6.2 with new logging approach they've brought up.
@EugeneYushin i suggest to downgrade and stick with 3.5.x
until unless https://liquibase.jira.com/browse/CORE-3220 will be resolved as for right now we have CLI which support --logLevel
argument which is not working.
@eseliavka-ias I've downgraded liqui to 3.5.2. Please, take a look one more time
Latest versions of cloudera and liquibase libs