Console logs not showing in Beeline

[#1]

Hello,

Console logs are not showing in beeline for one of the hiveserver2. But it is working fine with another hiveserver2.

Compared the beeline env variables from both HS2 servers and found a difference in below env variable.

env:CONSOLETYPE=vt

Hence I have tried to set "env:CONSOLETYPE=vt" through beeline, but it is throwing below error.

Appreciate your help on this.

============

0: jdbc:hive2://HS2-host:> set env:CONSOLETYPE=vt;
Getting log thread is interrupted, since query is done!
Error: Error while processing statement: null (state=,code=1)
org.apache.hive.service.cli.HiveSQLException: Error while processing statement: null
at org.apache.hive.jdbc.Utils.verifySuccess(Utils.java:239)
at org.apache.hive.jdbc.Utils.verifySuccessWithInfo(Utils.java:225)
at org.apache.hive.jdbc.HiveStatement.execute(HiveStatement.java:244)
at org.apache.hive.beeline.Commands.executeInternal(Commands.java:902)
at org.apache.hive.beeline.Commands.execute(Commands.java:1089)
at org.apache.hive.beeline.Commands.sql(Commands.java:985)
at org.apache.hive.beeline.BeeLine.dispatch(BeeLine.java:1085)
at org.apache.hive.beeline.BeeLine.execute(BeeLine.java:917)
at org.apache.hive.beeline.BeeLine.begin(BeeLine.java:845)
at org.apache.hive.beeline.BeeLine.mainWithInputRedirection(BeeLine.java:482)
at org.apache.hive.beeline.BeeLine.main(BeeLine.java:465)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.apache.hadoop.util.RunJar.run(RunJar.java:221)
at org.apache.hadoop.util.RunJar.main(RunJar.java:136)
Caused by: org.apache.hive.service.cli.HiveSQLException: Error while processing statement: null
at org.apache.hive.service.cli.operation.Operation.toSQLException(Operation.java:374)
at org.apache.hive.service.cli.operation.HiveCommandOperation.runInternal(HiveCommandOperation.java:116)
at org.apache.hive.service.cli.operation.Operation.run(Operation.java:316)
at org.apache.hive.service.cli.session.HiveSessionImpl.executeStatementInternal(HiveSessionImpl.java:424)
at org.apache.hive.service.cli.session.HiveSessionImpl.executeStatementAsync(HiveSessionImpl.java:401)
at org.apache.hive.service.cli.CLIService.executeStatementAsync(CLIService.java:258)
at org.apache.hive.service.cli.thrift.ThriftCLIService.ExecuteStatement(ThriftCLIService.java:503)
at org.apache.hive.service.cli.thrift.TCLIService$Processor$ExecuteStatement.getResult(TCLIService.java:1313)
at org.apache.hive.service.cli.thrift.TCLIService$Processor$ExecuteStatement.getResult(TCLIService.java:1298)
at org.apache.thrift.ProcessFunction.process(ProcessFunction.java:39)
at org.apache.thrift.TBaseProcessor.process(TBaseProcessor.java:39)
at org.apache.hive.service.auth.TSetIpAddressProcessor.process(TSetIpAddressProcessor.java:56)
at org.apache.thrift.server.TThreadPoolServer$WorkerProcess.run(TThreadPoolServer.java:286)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)

=========================

[#2]

Try it without env:

set CONSOLETYPE=vt;

This didn't throw errors for me. I did not test it further though to see if it actual changes anything.

[#3]

Thank you @mbigelow for your reply!

Setting the consoletype variable didn't helped here, still I am not getting console logs. It is just showing the output of the query without any console logs. Please find the below.

0: jdbc:hive2://HS2-node:> set CONSOLETYPE;
set
CONSOLETYPE=vt
1 row selected (0.072 seconds)

0: jdbc:hive2://HS2-node:> select count(*) from npevent;
_c0
253427762
1 row selected (305.41 seconds)

[#4]

Just to be clear, you want the output on the MR job launch and progress right?  Like this...

INFO : Compiling command(queryId=hive_20170208163838_f60cb50c-255e-4ea0-8c23-eb894bba7bbb): select distinct wafernum_part('fab.op2451',wafernum) from fab.op2451 where storeday in ("2017-01-05")
INFO : converting to local hdfs:/lib/business-dedupe-2.1.0.jar
INFO : Added [/tmp/2e04052d-c322-4047-a4d5-c52d67ddc46c_resources/business-dedupe-2.1.0.jar] to class path
INFO : Added resources: [hdfs:/lib/business-dedupe-2.1.0.jar]
INFO : Semantic Analysis Completed
INFO : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:_c0, type:string, comment:null)], properties:null)
INFO : Completed compiling command(queryId=hive_20170208163838_f60cb50c-255e-4ea0-8c23-eb894bba7bbb); Time taken: 0.253 seconds
INFO : Executing command(queryId=hive_20170208163838_f60cb50c-255e-4ea0-8c23-eb894bba7bbb): select distinct wafernum_part('fab.op2451',wafernum) from fab.op2451 where storeday in ("2017-01-05")
INFO : Query ID = hive_20170208163838_f60cb50c-255e-4ea0-8c23-eb894bba7bbb
INFO : Total jobs = 1
INFO : Launching Job 1 out of 1
INFO : Starting task [Stage-1:MAPRED] in serial mode
INFO : Number of reduce tasks not specified. Estimated from input data size: 1
INFO : In order to change the average load for a reducer (in bytes):
INFO : set hive.exec.reducers.bytes.per.reducer=<number>
INFO : In order to limit the maximum number of reducers:
INFO : set hive.exec.reducers.max=<number>
INFO : In order to set a constant number of reducers:
INFO : set mapreduce.job.reduces=<number>
INFO : number of splits:8
INFO : Submitting tokens for job: job_1486193162125_5338
INFO : Kind: HDFS_DELEGATION_TOKEN, Service: ha-hdfs:nameservice1, Ident: (token for mbige7303763: HDFS_DELEGATION_TOKEN owner=user, renewer=yarn, realUser=hive/hive_princ, issueDate=1486571884281, maxDate=1487176684281, sequenceNumber=67028, masterKeyId=147)
INFO : Kind: HIVE_DELEGATION_TOKEN, Service: HiveServer2ImpersonationToken, Ident: 00 0c 6d 62 69 67 65 37 33 30 33 37 36 33 0c 6d 62 69 67 65 37 33 30 33 37 36 33 2e 68 69 76 65 2f 61 62 6f 2d 6c 70 33 2d 65 78 74 65 64 30 31 2e 77 64 63 2e 63 6f 6d 40 48 49 54 41 43 48 49 47 53 54 2e 47 4c 4f 42 41 4c 8a 01 5a 1e 96 8f 7d 8a 01 5a 42 a3 13 7d 8e 0e b4 30
INFO : The url to track the job: https://RM_host:8090/proxy/application_1486193162125_5338/
INFO : Starting Job = job_1486193162125_5338, Tracking URL = https://RM_host:8090/proxy/application_1486193162125_5338/
INFO : Kill Command = /opt/cloudera/parcels/CDH-5.8.2-1.cdh5.8.2.p0.3/lib/hadoop/bin/hadoop job -kill job_1486193162125_5338
INFO : Hadoop job information for Stage-1: number of mappers: 8; number of reducers: 1
INFO : 2017-02-08 16:38:11,038 Stage-1 map = 0%, reduce = 0%
INFO : 2017-02-08 16:38:22,266 Stage-1 map = 13%, reduce = 0%, Cumulative CPU 12.78 sec
INFO : 2017-02-08 16:38:24,308 Stage-1 map = 14%, reduce = 0%, Cumulative CPU 116.9 sec
INFO : 2017-02-08 16:38:51,878 Stage-1 map = 27%, reduce = 0%, Cumulative CPU 329.89 sec
INFO : 2017-02-08 16:38:52,896 Stage-1 map = 39%, reduce = 0%, Cumulative CPU 330.75 sec
INFO : 2017-02-08 16:38:54,933 Stage-1 map = 52%, reduce = 0%, Cumulative CPU 346.65 sec
INFO : 2017-02-08 16:38:55,952 Stage-1 map = 64%, reduce = 0%, Cumulative CPU 348.19 sec
INFO : 2017-02-08 16:38:57,988 Stage-1 map = 84%, reduce = 0%, Cumulative CPU 358.66 sec
INFO : 2017-02-08 16:38:59,009 Stage-1 map = 95%, reduce = 0%, Cumulative CPU 360.07 sec
INFO : 2017-02-08 16:39:01,048 Stage-1 map = 100%, reduce = 0%, Cumulative CPU 363.5 sec
INFO : 2017-02-08 16:39:07,176 Stage-1 map = 100%, reduce = 100%, Cumulative CPU 367.49 sec
INFO : MapReduce Total cumulative CPU time: 6 minutes 7 seconds 490 msec
INFO : Ended Job = job_1486193162125_5338
INFO : MapReduce Jobs Launched:
INFO : Stage-Stage-1: Map: 8 Reduce: 1 Cumulative CPU: 367.49 sec HDFS Read: 942254005 HDFS Write: 64 SUCCESS
INFO : Total MapReduce CPU Time Spent: 6 minutes 7 seconds 490 msec
INFO : Completed executing command(queryId=hive_20170208163838_f60cb50c-255e-4ea0-8c23-eb894bba7bbb); Time taken: 64.188 seconds
INFO : OK

What are you logging levels in Hive, specifically for HS2?

HiveServer2 Logging Threshold in CM

[#5]

Yes @mbigelow. I am getting these logs in another HS2 server, but not in one of the HS2. 

[#6]

Both are managed by CM?

Can you track down the current process directory on both and compare the configs? The log settings should be in a log4j.properties file in the process config directory.

[#7]

HS2-1(Console log is generating)

==========================

hive.root.logger is not there in beeline env list, but still console log is generating in HS2-1

$ beeline --outputformat=tsv2 -u "jdbc:hive2://HS2-1:10000/default;" -n user -w ~/.pass -e 'set -v;' 2>/dev/null | grep root.logger
system:hadoop.root.logger=INFO,console

Hive root logger is set to INFO,console in configuration file. 

$ grep hive.root.logger /etc/hive/conf/log4j.properties
log4j.rootLogger=${hive.root.logger}
hive.root.logger=INFO,console

Console is generating when executing a query

0: jdbc:hive2://HS2-1😆 select count(*) from scecomm_account_console;
INFO : Compiling command(queryId=hive_20170208092828_aae117b5-eb16-489d-ba16-69aa30311ea2): select count(*) from scecomm_account_console
INFO : Semantic Analysis Completed
INFO : Returning Hive schema: Schema(fieldSchemas:[FieldSchema(name:_c0, type:bigint, comment:null)], properties:null)
INFO : Completed compiling command(queryId=hive_20170208092828_aae117b5-eb16-489d-ba16-69aa30311ea2); Time taken: 0.169 seconds
INFO : Executing command(queryId=hive_20170208092828_aae117b5-eb16-489d-ba16-69aa30311ea2): select count(*) from scecomm_account_console
INFO : Query ID = hive_20170208092828_aae117b5-eb16-489d-ba16-69aa30311ea2
INFO : Total jobs = 1
INFO : Launching Job 1 out of 1
INFO : Starting task [Stage-1:MAPRED] in serial mode
INFO : Number of reduce tasks determined at compile time: 1
INFO : In order to change the average load for a reducer (in bytes):
INFO : set hive.exec.reducers.bytes.per.reducer=<number>
INFO : In order to limit the maximum number of reducers:
INFO : set hive.exec.reducers.max=<number>
INFO : In order to set a constant number of reducers:
INFO : set mapreduce.job.reduces=<number>
INFO : number of splits:37
INFO : Submitting tokens for job: job_1486088124499_3537
INFO : The url to track the job: http://RM:8088/proxy/application_1486088124499_3537/
INFO : Starting Job = job_1486088124499_3537, Tracking URL = http://RM:8088/proxy/application_1486088124499_3537/
INFO : Kill Command = /opt/cloudera/parcels/CDH-5.8.2-1.cdh5.8.2.p0.3/lib/hadoop/bin/hadoop job -kill job_1486088124499_3537
INFO : Hadoop job information for Stage-1: number of mappers: 37; number of reducers: 1
INFO : 2017-02-08 09:28:25,516 Stage-1 map = 0%, reduce = 0%
INFO : 2017-02-08 09:28:35,814 Stage-1 map = 3%, reduce = 0%, Cumulative CPU 5.29 sec
INFO : 2017-02-08 09:28:38,896 Stage-1 map = 14%, reduce = 0%, Cumulative CPU 26.95 sec
INFO : 2017-02-08 09:28:44,021 Stage-1 map = 19%, reduce = 0%, Cumulative CPU 37.67 sec
INFO : 2017-02-08 09:28:47,103 Stage-1 map = 24%, reduce = 0%, Cumulative CPU 49.0 sec
INFO : 2017-02-08 09:28:48,126 Stage-1 map = 27%, reduce = 0%, Cumulative CPU 54.61 sec
INFO : 2017-02-08 09:28:50,191 Stage-1 map = 30%, reduce = 0%, Cumulative CPU 59.83 sec
INFO : 2017-02-08 09:28:52,247 Stage-1 map = 32%, reduce = 0%, Cumulative CPU 65.23 sec
INFO : 2017-02-08 09:28:53,277 Stage-1 map = 35%, reduce = 0%, Cumulative CPU 70.57 sec
INFO : 2017-02-08 09:28:56,359 Stage-1 map = 41%, reduce = 0%, Cumulative CPU 81.39 sec
INFO : 2017-02-08 09:28:57,394 Stage-1 map = 43%, reduce = 0%, Cumulative CPU 87.06 sec
INFO : 2017-02-08 09:28:59,443 Stage-1 map = 46%, reduce = 0%, Cumulative CPU 91.11 sec
INFO : 2017-02-08 09:29:00,474 Stage-1 map = 49%, reduce = 0%, Cumulative CPU 96.6 sec
INFO : 2017-02-08 09:29:03,554 Stage-1 map = 51%, reduce = 0%, Cumulative CPU 102.1 sec
INFO : 2017-02-08 09:29:05,600 Stage-1 map = 54%, reduce = 0%, Cumulative CPU 107.42 sec
INFO : 2017-02-08 09:29:06,632 Stage-1 map = 57%, reduce = 0%, Cumulative CPU 112.72 sec
INFO : 2017-02-08 09:29:09,710 Stage-1 map = 62%, reduce = 0%, Cumulative CPU 123.61 sec
INFO : 2017-02-08 09:29:14,840 Stage-1 map = 65%, reduce = 0%, Cumulative CPU 129.43 sec
INFO : 2017-02-08 09:29:15,863 Stage-1 map = 70%, reduce = 0%, Cumulative CPU 141.22 sec
INFO : 2017-02-08 09:29:18,935 Stage-1 map = 73%, reduce = 0%, Cumulative CPU 146.75 sec
INFO : 2017-02-08 09:29:20,988 Stage-1 map = 76%, reduce = 0%, Cumulative CPU 152.25 sec
INFO : 2017-02-08 09:29:22,016 Stage-1 map = 78%, reduce = 0%, Cumulative CPU 157.74 sec
INFO : 2017-02-08 09:29:24,059 Stage-1 map = 81%, reduce = 0%, Cumulative CPU 163.44 sec
INFO : 2017-02-08 09:29:25,079 Stage-1 map = 84%, reduce = 0%, Cumulative CPU 169.15 sec
INFO : 2017-02-08 09:29:28,147 Stage-1 map = 86%, reduce = 0%, Cumulative CPU 174.86 sec
INFO : 2017-02-08 09:29:29,170 Stage-1 map = 87%, reduce = 0%, Cumulative CPU 179.94 sec
INFO : 2017-02-08 09:29:31,216 Stage-1 map = 92%, reduce = 0%, Cumulative CPU 185.99 sec
INFO : 2017-02-08 09:29:32,240 Stage-1 map = 95%, reduce = 0%, Cumulative CPU 191.63 sec
INFO : 2017-02-08 09:29:35,317 Stage-1 map = 95%, reduce = 32%, Cumulative CPU 192.51 sec
INFO : 2017-02-08 09:29:36,348 Stage-1 map = 97%, reduce = 32%, Cumulative CPU 198.02 sec
INFO : 2017-02-08 09:29:40,454 Stage-1 map = 100%, reduce = 32%, Cumulative CPU 204.04 sec
INFO : 2017-02-08 09:29:41,487 Stage-1 map = 100%, reduce = 67%, Cumulative CPU 204.22 sec
INFO : 2017-02-08 09:29:42,515 Stage-1 map = 100%, reduce = 100%, Cumulative CPU 206.68 sec
INFO : MapReduce Total cumulative CPU time: 3 minutes 26 seconds 680 msec
INFO : Ended Job = job_1486088124499_3537
INFO : MapReduce Jobs Launched:
INFO : Stage-Stage-1: Map: 37 Reduce: 1 Cumulative CPU: 206.68 sec HDFS Read: 9856069385 HDFS Write: 9 SUCCESS
INFO : Total MapReduce CPU Time Spent: 3 minutes 26 seconds 680 msec
INFO : Completed executing command(queryId=hive_20170208092828_aae117b5-eb16-489d-ba16-69aa30311ea2); Time taken: 88.306 seconds
INFO : OK
_c0
54265941
1 row selected (88.51 seconds)

HS2-2(Console log is not generating)

=================================

Same root.logger properties for HS2-2 also, but it is not showing console logs.

$ beeline --outputformat=tsv2 -u "jdbc:hive2://HS2-2:10000/default;" -n user -w ~/.pass -e 'set -v;' 2>/dev/null | grep root.logger
system:hadoop.root.logger=INFO,console

Hive root logger is set to INFO,console in configuration file. 

$ grep hive.root.logger /etc/hive/conf/log4j.properties
log4j.rootLogger=${hive.root.logger}
hive.root.logger=INFO,console

Console log is not generating while connecting to HS2-2

0: jdbc:hive2://HS2-2😆 select count(*) from scecomm_account_console;
_c0
54265941

Tried to set hive.root.logger manually, but still no luck.

0: jdbc:hive2://HS2-2😆 set hive.root.logger=INFO,console;
No rows affected (0.002 seconds)
0: jdbc:hive2://HS2-2😆 set hive.root.logger;
set
hive.root.logger=INFO,console
1 row selected (0.005 seconds)

0: jdbc:hive2://HS2-2😆 select count(*) from scecomm_account_console;
_c0
54265941
1 row selected (143.116 seconds)

[#8]

All nodes are managed by CM and there is no difference in /etc/hive/conf/log4j.properties of both HS2 servers.

[#9]

Check the env var for hive.session.silent and just silent. Mine are false and off for both.

Also try launching beeline with --silent=false switch to see if that forces to out and to see if it is not logger related.

[#10]

For both HS2 servers, env variable hive.session.silent is set to false already. However I have tried to use --silent=false, but no luck.