1 2 Previous Next 27 Replies Latest reply on Feb 14, 2021 10:43 PM by Andrea Gruev

    DEI writing to Hive with Kerberos

    Andrea Gruev Active Member

      Greetings everyone,

       

      What we are trying to achieve is to read and write data in Hive.

       

      Setup is the following:

        Server1 (Centos 7):

           DIS is running and its enabled to use OS profile. Hadoop Kerberos service principal and Keytab are used.

           Meta Access Service is configured to use OS profile and impersonation and impersonation user to be the one that will login to Developer. Same principal and Keytab is used here.

           OS profile is configured for DEI and MAS services. System user is infa.

           LDAPS is configured and domain users are the one used to login into the Developer tool. KDC is running on the domain.

       

      Server2 (Hortonworks HDP 2.6.5)

           Ranger is synced with the same AD. Users are granted access to all services on the HDP.

           Proxy user is added to core-site.xml (ex. hadoop.proxyuser.hdp_service.groups=* , hadoop.proxyuser.hdp_service.hosts=* and hadoop.proxyuser.hdp_service.users=*)

           hdp_service should be the proxy user.

           Hive is configured to run as end user instead of Hive user.

       

      Before enabling Kerberos on Server2 I was able to read/write to hive in Native Runtime when I use my AD account aka in Hive connection I put my Windows username and password. Also I was able to pushdown the execution with Spark.

       

      After Kerberos enablement on Server2 I am able only to read the data into the hive tables but I`m not able to write.

      In HDFS config dfs.datanode.address change to port 1019 and dfs.datanode.http.address change to 1022.

      Both ports are open and can be reached from Server1. Cluster configuration was refreshed on the Server1 (aka Informatica server) after the change on the authentication.

       

      When review the logs of the failing job I can see the following errors :

      " ...

      ...

      xxxxxxx 20:34:17.356 <TASK_140385267431168-READER_1_1_1> INFO: [RR_4045] SQL warnings [

      Function [INFASQLFetch] failed in adapter [/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [100].]

      xxxxxxx 20:34:17.464 <TASK_140385267431168-READER_1_1_1> INFO: [CMN_1053] Read_days:Exchange: Control=[EOF]

      Read_days:Exchange: Rowdata: ( RowType=0(insert) Src Rowid=1 Targ Rowid=1

        day (day:Int:): "1"

      )

      ...

      ...

      xxxxxxx 20:34:25.627 <TASK_140385284216576-WRITER_1_*_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_hdp]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=File /tmp/days_nums_1602956052678/days_nums_1602956052678_0 could only be replicated to 0 nodes instead of minReplication (=1).  There are 1 datanode(s) running and 1 node(s) are excluded in this operation.

          at org.apache.hadoop.hdfs.server.blockmanagement.BlockManager.chooseTarget4NewBlock(BlockManager.java:1719)

          at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getNewBlockTargets(FSNamesystem.java:3372)

          at org.apache.hadoop.hdfs.server.namenode.FSNamesystem.getAdditionalBlock(FSNamesystem.java:3296)

          at org.apache.hadoop.hdfs.server.namenode.NameNodeRpcServer.addBlock(NameNodeRpcServer.java:850)

          at org.apache.hadoop.hdfs.protocolPB.ClientNamenodeProtocolServerSideTranslatorPB.addBlock(ClientNamenodeProtocolServerSideTranslatorPB.java:504)

          at org.apache.hadoop.hdfs.protocol.proto.ClientNamenodeProtocolProtos$ClientNamenodeProtocol$2.callBlockingMethod(ClientNamenodeProtocolProtos.java)

          at org.apache.hadoop.ipc.ProtobufRpcEngine$Server$ProtoBufRpcInvoker.call(ProtobufRpcEngine.java:640)

          at org.apache.hadoop.ipc.RPC$Server.call(RPC.java:982)

          at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2351)

          at org.apache.hadoop.ipc.Server$Handler$1.run(Server.java:2347)

          at java.security.AccessController.doPrivileged(Native Method)

          at javax.security.auth.Subject.doAs(Subject.java:422)

          at org.apache.hadoop.security.UserGroupInformation.doAs(UserGroupInformation.java:1869)

          at org.apache.hadoop.ipc.Server$Handler.run(Server.java:2347)

       

      ]

      xxxxxxx 20:34:25.635 <TASK_140385284216576-WRITER_1_*_1> SEVERE: [WRT_8229] Database errors occurred:

      Function [INFASQLFreeHandle] failed in adapter [/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

      2020-10-17 20:34:25.644 <TASK_140385284216576-WRITER_1_*_1> SEVERE: [WRT_8186] Error while initializing load. Writer run terminated.

      ...

      ...

      ...

      xxxxxxx  20:34:25.915 <APP_140385570559744> INFO: [TM_6020] Session [m_H2H] completed at [].

      xxxxxxx  20:34:25.500 <OnDemandDTM-pool-2-thread-41> SEVERE: [EdtmExec_00007] WRT_8229 Database errors occurred:

      Function [INFASQLFreeHandle] failed in adapter [/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

      xxxxxxx  20:34:25.943 <OnDemandDTM-pool-2-thread-41> WARNING: [EdtmExec_00007] WRT_8229 Database errors occurred:

      Function [INFASQLFreeHandle] failed in adapter [/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

      xxxxxxx  20:34:25.952 <OnDemandDTM-pool-2-thread-41> FINE: com.informatica.sdk.dtm.ExecutionException: [EdtmExec_00007] WRT_8229 Database errors occurred:

      Function [INFASQLFreeHandle] failed in adapter [/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

          at com.informatica.dtm.executor.edtm.EdtmExecutor.createAndExeJdtm(EdtmExecutor.java:492)

          at com.informatica.dtm.executor.edtm.EdtmExecutor.run(EdtmExecutor.java:293)

          at com.informatica.platform.ldtm.executor.ExecutionEngine$SubmittedRunnable.run(ExecutionEngine.java:593)

          at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

          at java.util.concurrent.FutureTask.run(FutureTask.java:266)

          at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

          at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

          at java.lang.Thread.run(Thread.java:748)

       

      xxxxxxx  20:34:25.962 <OnDemandDTM-pool-2-thread-41> INFO: [EdtmExec_00008] Total time to perform the LDTM operation: 23,040 ms

       

      Could you please help me resolve that issue ?

       

      Regards!

        • 1. Re: DEI writing to Hive with Kerberos
          Krishnan Sreekandath Seasoned Veteran

          Hello Andrea,

           

          Based on the error message below, it seems the issue might be at the Hadoop cluster side where the name node and data node might be unhealthy or out of space.

           

          Can you please check ? Also, please do try to perform the same insert outside of DEI as well, like using beeline.

           

          xxxxxxx 20:34:25.627 <TASK_140385284216576-WRITER_1_*_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_hdp]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=File /tmp/days_nums_1602956052678/days_nums_1602956052678_0 could only be replicated to 0 nodes instead of minReplication (=1).  There are 1 datanode(s) running and 1 node(s) are excluded in this operation.

           

          Thanks,

          Krishnan

          • 2. Re: DEI writing to Hive with Kerberos
            Andrea Gruev Active Member

            Greetings ksreekan,

             

            I`ve checked the free space and we have it. Actually what I`m processing are 12 number 1-12.

            Installation of beeline on the DIS node just complete and now I have the following error once I`ve tried to connect:

            Error: Could not open client transport for any of the Server URI's in ZooKeeper: Unable to read HiveServer2 uri from ZooKeeper (state=08S01,code=0)

             

            beeline -u "jdbc:hive2://XXXX:2181/;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;saslQop=auth;principal=hive/_HOST@PRODUCTION.LOCAL"

             

            Does it mandatory for ZooKeeper to use Nifi?

            Should I use proxy user into the connection string? I`m using proxy user but right now I kinit with my own user that have access to hive db`s.

             

            I`m able from inside to beeline with the same link with same keytab and read/write data.

             

            Any ideas ?

             

            Regards,

            Andrea G.

            • 3. Re: DEI writing to Hive with Kerberos
              Andrea Gruev Active Member

              Greetings all,

               

              After some changes I`m able to connect to Hive from Beeline using the Impersonation user keytab and my user keytab. I`m able to select/delete/create tables.

               

              When I go to Informatica developer I`m only to view the tables but when try to view the data I got:

               

              <OnDemandDTM-pool-2-thread-6> WARNING: [EdtmExec_00007] RR_4036 Error connecting to database [

              Function [INFASQLConnectW] failed in adapter [/appl/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

               

              Database driver error...

              Function Name : Connect

              Database driver error...

              Function Name : Connect

              Database Error: Failed to connect to database using user [] and connection string [jdbc:hive2:/Host1:2181,Host2:2181,Host3:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;ssl=true;transportMode=http;httpPath=cliservice;saslQop=auth;principal=hive/_HOST@TESTAD.LOCAL].].

              2020-10-21 11:58:55.163 <OnDemandDTM-pool-2-thread-6> INFO: [EdtmExec_00008] Total time to perform the LDTM operation: 4,609 ms

               

              Regards,

              Andrea G.

              • 4. Re: DEI writing to Hive with Kerberos
                Vlad Ponomarenko Guru

                Hi,

                Please, check Configure the Data Integration Service.

                Our customers often forgot about  folder <Informatica installation directory>/java/jre/lib/security

                 

                 

                Regards, Vlad

                • 5. Re: DEI writing to Hive with Kerberos
                  Andrea Gruev Active Member

                  Greetings Vlad,

                  I`ve checked and krb5.conf file is there. Thanks for your response Vladislav00u15jntowwRQeXYF1d8

                  Regards,

                  Andrea G.

                  • 6. Re: DEI writing to Hive with Kerberos
                    Krishnan Sreekandath Seasoned Veteran

                    Hello Andrea,

                     

                    Can you please rerun the data viewer on the same object with verbose initialization override tracing level ?

                     

                    If there are errors then it should show up in verbose init logs right before your error above.

                     

                    If we still don't see any errors, then I would request you to check the HiveServer2 logs as well. For ease of troubleshooting, I suppose we can point it to a single HiveServer2 instead of using Zookeeper discovery mode.

                     

                    Also, I hope this error is not just for one table and is present for others in the Hive database as well.

                     

                    Thanks,

                    Krishnan

                    • 7. Re: DEI writing to Hive with Kerberos
                      Andrea Gruev Active Member

                      Greetings Krishnan,

                       

                      This is the Informatica log from the session:

                       

                       

                      2020-10-21 15:00:03.727 <MappingCompiler-pool-4-thread-9> INFO: [MPSVCCMN_10083] The Mapping Service Module submitted a job to the Integration Service.  Job ID : [Vdxb5BOdEeuEL2lJL52qVA]

                      2020-10-21 15:00:03.742 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_4806] The mapping is being executed with operating system profile [Idip_Service_Profile].

                      2020-10-21 15:00:03.748 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/appl/nas/informatica/TRANSFER/dis_shared_dir/reject] for the system parameter [RejectDir].

                      2020-10-21 15:00:03.753 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/tmp] for the system parameter [StateStore].

                      2020-10-21 15:00:03.759 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/appl/nas/informatica/TRANSFER/dis_shared_dir/cache] for the system parameter [CacheDir].

                      2020-10-21 15:00:03.764 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/appl/nas/informatica/TRANSFER/dis_shared_dir/disTemp] for the system parameter [TempDir].

                      2020-10-21 15:00:03.769 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/appl/nas/informatica/TRANSFER/dis_shared_dir/target] for the system parameter [TargetDir].

                      2020-10-21 15:00:03.774 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [DIS_TEST] for the system parameter [ServiceName].

                      2020-10-21 15:00:03.780 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/appl/nas/informatica/TRANSFER/dis_shared_dir/source] for the system parameter [SourceDir].

                      2020-10-21 15:00:03.785 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [Preview] for the system parameter [ApplicationName].

                      2020-10-21 15:00:03.792 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [testad.local\t_gruevan] for the system parameter [UserName].

                      2020-10-21 15:00:03.797 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [test_infa] for the system parameter [MappingName].

                      2020-10-21 15:00:03.802 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [10/21/2020 15:00:03] for the system parameter [MappingRunStartTime].

                      2020-10-21 15:00:03.807 <MappingCompiler-pool-4-thread-9> INFO: [LDTMPARAM_0013] The Integration Service uses the value [native] for the system parameter [ExecutionEnvironment].

                      2020-10-21 15:00:03.825 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0117] Choose mapping execution engine [Native engine].

                      2020-10-21 15:00:03.831 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0026] LDTM: Starting mapping compilation.

                      2020-10-21 15:00:03.839 <MappingCompiler-pool-4-thread-9> INFO: [LDTMCMN_0037] The Hadoop distribution directory is defined in Data Integration Service properties at the path [/appl/opt/infa/services/shared/hadoop/HDP_3.1.5].

                      2020-10-21 15:00:03.848 <MappingCompiler-pool-4-thread-9> INFO: [CLUSTERCONF_10024] The cluster configuration [BigData_Sandbox] is unchanged from the last export. Using the existing export file [/appl/nas/informatica/TRANSFER/dis_shared_dir/disTemp/infa_test/DIS_TEST/node01/bigdata_sandbox/NATIVE/e4114dfc-901e-4359-ba0a-e2fc5235f2f5/infacco-site.xml].

                      2020-10-21 15:00:03.855 <MappingCompiler-pool-4-thread-9> INFO: [CLUSTERCONF_10028] Based on the distribution [HORTONWORKS] and the run-time engine [NATIVE], the Data Integration Service will override the following cluster configuration properties at run time: null

                      2020-10-21 15:00:03.862 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0027] LDTM: Mapping compilation done.

                      2020-10-21 15:00:03.934 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0035] LDTM: Starting mapping translation.

                      2020-10-21 15:00:03.942 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0036] LDTM: Mapping translation finished.

                      2020-10-21 15:00:03.948 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_4600] LDTM: Detecting the data movement mode for the mapping.

                      2020-10-21 15:00:03.955 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_4601] LDTM: Setting the data movement mode for the mapping to [UNICODE].

                      2020-10-21 15:00:03.962 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_1202] LDTM: Starting mapping simplification.

                      2020-10-21 15:00:03.969 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_1203] LDTM: Mapping simplification complete.

                      2020-10-21 15:00:03.975 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0028] LDTM: Optimizing mapping...

                      2020-10-21 15:00:03.982 <MappingCompiler-pool-4-thread-9> INFO: [OPT_1600] The Integration Service is extracting constraints from sources.

                      2020-10-21 15:00:03.989 <MappingCompiler-pool-4-thread-9> INFO: [OPT_1603] The Integration Service is extracting constraints from the source [test_infa].

                      2020-10-21 15:00:03.995 <MappingCompiler-pool-4-thread-9> INFO: [OPT_1601] The Integration Service has finished extracting constraints from sources.

                      2020-10-21 15:00:04.002 <MappingCompiler-pool-4-thread-9> INFO: [OPT_1300] Running expression simplifier.

                      2020-10-21 15:00:04.007 <MappingCompiler-pool-4-thread-9> INFO: Starting early uncorrelated subquery optimization.

                      2020-10-21 15:00:04.012 <MappingCompiler-pool-4-thread-9> INFO: Early uncorrelated subquery optimization is finished.

                      2020-10-21 15:00:04.017 <MappingCompiler-pool-4-thread-9> INFO: [OPT_1700] The Integration Service is starting the Global Predicate Optimization method.

                      2020-10-21 15:00:04.040 <MappingCompiler-pool-4-thread-9> INFO: [OPT_1701] The Integration Service has finished applying the Global Predicate Optimization method.

                      2020-10-21 15:00:04.047 <MappingCompiler-pool-4-thread-9> INFO: [OPT_0500] Predicate optimization is starting.

                      2020-10-21 15:00:04.054 <MappingCompiler-pool-4-thread-9> INFO: [OPT_0501] Predicate optimization is finished.

                      2020-10-21 15:00:04.062 <MappingCompiler-pool-4-thread-9> INFO: Predicate minimization is starting.

                      2020-10-21 15:00:04.069 <MappingCompiler-pool-4-thread-9> INFO: Predicate minimization is finished.

                      2020-10-21 15:00:04.076 <MappingCompiler-pool-4-thread-9> INFO: [OPT_1300] Running expression simplifier.

                      2020-10-21 15:00:04.082 <MappingCompiler-pool-4-thread-9> INFO: [OPT_0008] Early projection optimization is starting.

                      2020-10-21 15:00:04.089 <MappingCompiler-pool-4-thread-9> INFO: [OPT_0009] Early projection optimization is finished.

                      2020-10-21 15:00:04.095 <MappingCompiler-pool-4-thread-9> INFO: [OPT_1400] The integration service is pruning the mapping.

                      2020-10-21 15:00:04.104 <MappingCompiler-pool-4-thread-9> INFO: [OPT_1401] The integration service has finished pruning the mapping.

                      2020-10-21 15:00:04.110 <MappingCompiler-pool-4-thread-9> INFO: [OPT_63306] Pushdown optimization is not enabled for this mapping.

                      2020-10-21 15:00:04.116 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0029] LDTM: Mapping optimization done.

                      2020-10-21 15:00:04.122 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0038] LDTM: Starting operations on data sources after optimization.

                      2020-10-21 15:00:04.128 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0039] LDTM: Post-optimization tasks for operations on data sources are complete.

                      2020-10-21 15:00:04.135 <MappingCompiler-pool-4-thread-9> INFO: [OPT_1900] Native Expression transformation optimization is starting.

                      2020-10-21 15:00:04.141 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_3013] The mapping cannot be partitioned because it limits the number of rows read from the source.

                      2020-10-21 15:00:04.147 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_3001] Partitioning is disabled for the mapping.

                      2020-10-21 15:00:04.154 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_1204] LDTM: Starting mapping simplification clean up.

                      2020-10-21 15:00:04.161 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_1205] LDTM: Mapping simplification clean up complete.

                      2020-10-21 15:00:04.169 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0030] LDTM: Preparing to execute the mapping.

                      2020-10-21 15:00:04.177 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_6068] Informatica os name is [Linux] and version is [3.10.0-1062.el7.x86_64].

                      2020-10-21 15:00:04.183 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_6069] Informatica user name is [idip].

                      2020-10-21 15:00:04.189 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_6070] Service Principal name is [t_svc_idi_service@TESTAD.LOCAL].

                      2020-10-21 15:00:04.196 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_7009] Following properties have values different than their default values. Effective values for these properties are as follows:

                        - INFA_INTERNAL_MAPPING_PREVIEW_EXECUTION: true

                        - CreateDirectoryIfNotExists: YES

                        - EnableConnectionPooling: Yes

                        - EnableConnectionPoolingForPrePostSQL: No

                        - DataMovementMode: UNICODE

                      2020-10-21 15:00:04.202 <MappingCompiler-pool-4-thread-9> INFO: [LDTM_0074] Total time to create the LDTM: 461 ms

                      2020-10-21 15:00:04.221 <MappingCompiler-pool-4-thread-9> INFO: [DS_10178] The job is running on Integration Service [DIS_TEST]. The Launch Job Options for the service is set to: [In separate local processes (OUT_OF_PROCESS)].

                      2020-10-21 15:00:04.228 <MappingCompiler-pool-4-thread-9> INFO: [ExecsCmn_00008] LDTM Output Stream is encoded in [Fast Infoset] format.

                      2020-10-21 15:00:04.239 <APP_OnDemandDTM-pool-2-thread-9> INFO: [JDTM_10055] The Integration Service is dispatching the job with operating system profile [Idip_Service_Profile] to the DTM process [DTMProcess_4].

                      2020-10-21 15:00:04.269 <APP_140532135229184> INFO: [TM_6982] DTM resource allocation policy: [OnDemand]; Time slice: [0] milliseconds; Data slice: [0] KB.

                      2020-10-21 15:00:04.277 <APP_140532135229184> INFO: [VAR_27079] Warning: server variable :[$PMExtProcDir], NULL override value not valid. The override value is set to empty string.

                      2020-10-21 15:00:04.288 <APP_140532135229184> INFO: [DISP_20305] The [Master] DTM with process id [306] is running on node [node01].

                       

                      2020-10-21 15:00:04.297 <APP_140532135229184> INFO: [TM_6964] Date format for the Session is [MM/DD/YYYY HH24:MI:SS]

                      2020-10-21 15:00:04.303 <APP_140532135229184> INFO: [TM_6983] Size of the thread pool that the DTM uses to allocate CPU resources: [16].

                      2020-10-21 15:00:04.310 <APP_140532203128576> INFO: [TM_6721] Started [Partition Group Formation].

                      2020-10-21 15:00:04.316 <APP_140532203128576> INFO: [TM_6722] Finished [Partition Group Formation].  It took [0.000637054] seconds.

                      2020-10-21 15:00:04.322 <APP_140532203128576> INFO: [TM_6014] Initializing session [test_infa] at [Wed Oct 21 15:00:04 2020].

                      2020-10-21 15:00:04.330 <APP_140532203128576> INFO: [TM_6101] Mapping name: test_infa.

                      2020-10-21 15:00:04.337 <APP_140532203128576> INFO: [TM_6708] Using configuration property [EnableConnectionPooling,Yes]

                      2020-10-21 15:00:04.344 <APP_140532203128576> INFO: [TM_6708] Using configuration property [EnableConnectionPoolingForPrePostSQL,No]

                      2020-10-21 15:00:04.350 <APP_140532203128576> INFO: [TM_6708] Using configuration property [LkupRemoveOrderBy,Yes]

                      2020-10-21 15:00:04.356 <APP_140532203128576> INFO: [TM_6708] Using configuration property [CreateDirectoryIfNotExists,YES]

                      2020-10-21 15:00:04.361 <APP_140532203128576> INFO: [TM_6708] Using configuration property [lookupOverrideParsingSetting,-1]

                      2020-10-21 15:00:04.367 <APP_140532203128576> INFO: [TM_6703] Session [test_infa] is run by 64-bit Data Integration Service  [DIS_TEST], version [10.4.1], build [195].

                      2020-10-21 15:00:04.371 <TASK_140531111810816-MAPPING> INFO: [PETL_24000] Parallel Pipeline Engine initializing.

                      2020-10-21 15:00:04.377 <TASK_140531111810816-MAPPING> INFO: [PETL_24001] Parallel Pipeline Engine running.

                      2020-10-21 15:00:04.383 <TASK_140531111810816-MAPPING> INFO: [CMN_1569] Server Mode: [UNICODE]

                      2020-10-21 15:00:04.388 <TASK_140531111810816-MAPPING> INFO: [CMN_1570] Server Code page: [UTF-8 encoding of Unicode]

                      2020-10-21 15:00:04.396 <TASK_140531111810816-MAPPING> INFO: [TM_6151] The session sort order is [Binary].

                      2020-10-21 15:00:04.402 <TASK_140531111810816-MAPPING> INFO: [TM_6185] Warning. Code page validation is disabled in this session.

                      2020-10-21 15:00:04.408 <TASK_140531111810816-MAPPING> INFO: [TM_6705] Session is running with test load option turned on for 1000 rows.

                      2020-10-21 15:00:04.413 <TASK_140531111810816-MAPPING> INFO: [TM_6165] The error threshold value = [0].

                      2020-10-21 15:00:04.418 <TASK_140531111810816-MAPPING> INFO: [TM_6155] Using HIGH precision processing.

                      2020-10-21 15:00:04.427 <TASK_140531111810816-MAPPING> INFO: [TM_6180] Deadlock retry logic will not be implemented.

                      2020-10-21 15:00:04.433 <TASK_140531111810816-MAPPING> INFO: [SDKS_38024] Plug-in 10000000 initialization complete.

                      2020-10-21 15:00:04.439 <TASK_140531111810816-MAPPING> INFO: [SDKS_38017] Writer SDK plug-in initialization complete.

                      2020-10-21 15:00:04.445 <TASK_140531111810816-MAPPING> INFO: [SDKS_38509] SDK target and group initialization complete.

                      2020-10-21 15:00:04.453 <TASK_140531111810816-MAPPING> INFO: [TM_6307] DTM error log disabled.

                      2020-10-21 15:00:04.461 <TASK_140531111810816-MAPPING> INFO: [TE_7022] TShmWriter: Initialized

                      2020-10-21 15:00:04.470 <TASK_140531111810816-MAPPING> INFO: [TM_6007] DTM initialized successfully for session [test_infa]

                      2020-10-21 15:00:04.476 <TASK_140531111810816-MAPPING> INFO: [PETL_24003] Initializing session run.

                      2020-10-21 15:00:04.483 <TASK_140531111810816-PRE-SESS> INFO: [PETL_24004] Starting pre-session tasks.

                      2020-10-21 15:00:04.489 <TASK_140531111810816-PRE-SESS> INFO: [PETL_24027] Pre-session task completed successfully.

                      2020-10-21 15:00:04.496 <TASK_140531111810816-MAPPING> INFO: [PETL_24006] Starting data movement.

                      2020-10-21 15:00:04.503 <TASK_140531111810816-MAPPING> INFO: [TM_6660] Total Buffer Pool size is 1179648 bytes and Block size is 65536 bytes.

                      2020-10-21 15:00:04.511 <TASK_140531120203520-READER_1_1_1> INFO: [DBG_21438] Reader: Source is [jdbc:hive2://Host1:2181,Host2:2181,Host3:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;ssl=true;transportMode=http;httpPath=cliservice;saslQop=auth;principal=hive/_HOST@TESTAD.LOCAL;hive.server2.proxy.user=t_svc_idi_service], user []

                      2020-10-21 15:00:04.518 <TASK_140531120203520-READER_1_1_1> INFO: [ODL_26122] The Integration Service does not use a connection pool for connection [HIVE_bigdata_sandbox].

                      2020-10-21 15:00:04.526 <TASK_140531120203520-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [

                      Error action file of type [Database] is set to file [NULL] for adapter [com.informatica.adapter.Hive.HiveConnectInfo].

                      Error action file of type [User] is set to file [NULL] for adapter [com.informatica.adapter.Hive.HiveConnectInfo].]

                      2020-10-21 15:00:04.534 <TASK_140531120203520-READER_1_1_1> INFO: [BLKR_16051] Source database connection [HIVE_bigdata_sandbox] code page: [UTF-8 encoding of Unicode]

                      2020-10-21 15:00:04.612 <TASK_140531120203520-READER_1_1_1> SEVERE: [RR_4036] Error connecting to database [

                      Function [INFASQLConnectW] failed in adapter [/appl/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

                       

                      Database driver error...

                      Function Name : Connect

                      Database driver error...

                      Function Name : Connect

                      Database Error: Failed to connect to database using user [] and connection string [jdbc:hive2://Host1:2181,Host2:2181,Host3:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;ssl=true;transportMode=http;httpPath=cliservice;saslQop=auth;principal=hive/_HOST@TESTAD.LOCAL;hive.server2.proxy.user=t_svc_idi_service].].

                      2020-10-21 15:00:04.620 <TASK_140531120203520-READER_1_1_1> SEVERE: [BLKR_16001] Error connecting to database...

                      2020-10-21 15:00:04.627 <TASK_140531111810816-MAPPING> INFO: [PETL_24031]

                      ***** RUN INFO FOR TGT LOAD ORDER GROUP [1], CONCURRENT SET [1] *****

                      Completed the [reader] stage of the partition point [test_infa]. The run time is not sufficient to report any statistics.

                       

                      2020-10-21 15:00:04.627 <OnDemandDTM-pool-2-thread-9> SEVERE: [EdtmExec_00007] RR_4036 Error connecting to database [

                      Function [INFASQLConnectW] failed in adapter [/appl/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

                       

                      Database driver error...

                      Function Name : Connect

                      Database driver error...

                      Function Name : Connect

                      Database Error: Failed to connect to database using user [] and connection string [jdbc:hive2://Host1:2181,Host2:2181,Host3:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;ssl=true;transportMode=http;httpPath=cliservice;saslQop=auth;principal=hive/_HOST@TESTAD.LOCAL;hive.server2.proxy.user=t_svc_idi_service].].

                      2020-10-21 15:00:04.633 <TASK_140531103418112-POST-SESS> INFO: [PETL_24005] Starting post-session tasks.

                      2020-10-21 15:00:04.647 <TASK_140531103418112-POST-SESS> INFO: [PETL_24028] Post-session task completed with failure.

                      2020-10-21 15:00:04.653 <TASK_140531103418112-MAPPING> INFO: [SDKS_38510] SDK target and group deinitialized with status [-1].

                      2020-10-21 15:00:04.658 <TASK_140531103418112-MAPPING> INFO: [SDKS_38025] Plug-in 10000000 deinitialized and unloaded with status [-1].

                      2020-10-21 15:00:04.666 <TASK_140531103418112-MAPPING> INFO: [SDKS_38019] Writer SDK plug-ins deinitialized with status [-1].

                      2020-10-21 15:00:04.671 <TASK_140531103418112-MAPPING> INFO: [TM_6018] The session completed with [0] row transformation errors.

                      2020-10-21 15:00:04.676 <TASK_140531103418112-MAPPING> INFO: [PETL_24002] Parallel Pipeline Engine finished.

                      2020-10-21 15:00:04.682 <APP_140532203128576> INFO: [PETL_24013] Session run completed with failure.

                      2020-10-21 15:00:04.688 <APP_140532203128576> INFO: [TM_6022]

                       

                      SESSION LOAD SUMMARY

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

                       

                      2020-10-21 15:00:04.695 <APP_140532203128576> INFO: [TM_6252] Source Load Summary.

                      2020-10-21 15:00:04.700 <APP_140532203128576> INFO: [CMN_1740] Table: [test_infa] (Instance Name: [test_infa])

                           Output Rows [0], Affected Rows [0], Applied Rows [0], Rejected Rows [0]

                      2020-10-21 15:00:04.706 <APP_140532203128576> INFO: [TM_6704] Target Test Load Summary

                      2020-10-21 15:00:04.712 <APP_140532203128576> INFO: [CMN_1740] Table: [Data_Exchange_Target-expr_OutputParameters_OUTPUT] (Instance Name: [Data_Exchange_Target-expr_OutputParameters_OUTPUT])

                           Output Rows [0], Affected Rows [0], Applied Rows [0], Rejected Rows [0]

                      2020-10-21 15:00:04.718 <APP_140532203128576> INFO: [TM_6023]

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

                       

                      2020-10-21 15:00:04.724 <APP_140532203128576> INFO: [TM_6020] Session [test_infa] completed at [Wed Oct 21 15:00:04 2020].

                      2020-10-21 15:00:04.732 <OnDemandDTM-pool-2-thread-9> WARNING: [EdtmExec_00007] RR_4036 Error connecting to database [

                      Function [INFASQLConnectW] failed in adapter [/appl/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

                       

                      Database driver error...

                      Function Name : Connect

                      Database driver error...

                      Function Name : Connect

                      Database Error: Failed to connect to database using user [] and connection string [jdbc:hive2://Host1:2181,Host2:2181,Host3:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;ssl=true;transportMode=http;httpPath=cliservice;saslQop=auth;principal=hive/_HOST@TESTAD.LOCAL;hive.server2.proxy.user=t_svc_idi_service].].

                      2020-10-21 15:00:04.740 <OnDemandDTM-pool-2-thread-9> INFO: [EdtmExec_00008] Total time to perform the LDTM operation: 504 ms

                       

                      • 8. Re: DEI writing to Hive with Kerberos
                        Andrea Gruev Active Member

                        This is the Hive servers log:

                         

                        SERVER1-

                        2020-10-21T15:00:40,705 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: thrift.ThriftHttpServlet (:()) - Could not validate cookie sent, will try to generate a new cookie

                        2020-10-21T15:00:40,706 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: thrift.ThriftHttpServlet (:()) - Failed to authenticate with http/_HOST kerberos principal, trying with hive/_HOST kerberos principal

                        2020-10-21T15:00:40,706 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: thrift.ThriftHttpServlet (:()) - Cookie added for clientUserName ambari-qa

                        2020-10-21T15:00:40,707 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: thrift.ThriftCLIService (:()) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V10

                        2020-10-21T15:00:40,708 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI thrift://Hive0d:9083

                        2020-10-21T15:00:40,708 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.HiveMetaStoreClient (:()) - HMSC::open(): Could not find delegation token. Creating KERBEROS-based thrift connection.

                        2020-10-21T15:00:40,710 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore, current connections: 8

                        2020-10-21T15:00:40,710 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.HiveMetaStoreClient (:()) - Connected to metastore.

                        2020-10-21T15:00:40,710 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive/Hive2d@TESTAD.LOCAL (auth:KERBEROS) retries=24 delay=5 lifetime=0

                        2020-10-21T15:00:40,735 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: session.SessionState (:()) - Created HDFS directory: /tmp/hive/ambari-qa/4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:40,737 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: session.SessionState (:()) - Created local directory: /tmp/hive/4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:40,740 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: session.SessionState (:()) - Created HDFS directory: /tmp/hive/ambari-qa/4571b2e9-cad0-416d-b601-f6df5de91068/_tmp_space.db

                        2020-10-21T15:00:40,740 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore, current connections: 7

                        2020-10-21T15:00:40,741 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI thrift://Hive0d:9083

                        2020-10-21T15:00:40,741 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.HiveMetaStoreClient (:()) - HMSC::open(): Found delegation token. Creating DIGEST-based thrift connection.

                        2020-10-21T15:00:40,743 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore, current connections: 8

                        2020-10-21T15:00:40,743 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.HiveMetaStoreClient (:()) - Connected to metastore.

                        2020-10-21T15:00:40,743 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=ambari-qa (auth:PROXY) via hive/Hive2d@TESTAD.LOCAL (auth:KERBEROS) retries=24 delay=5 lifetime=0

                        2020-10-21T15:00:40,904 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: session.HiveSessionImpl (:()) - Operation log session directory is created: /tmp/hive/operation_logs/4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:40,904 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: service.CompositeService (:()) - Session opened, SessionHandle [4571b2e9-cad0-416d-b601-f6df5de91068], current sessions:3

                        2020-10-21T15:00:40,989 INFO  [HiveServer2-HttpHandler-Pool: Thread-6083]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:40,989 INFO  [4571b2e9-cad0-416d-b601-f6df5de91068 HiveServer2-HttpHandler-Pool: Thread-6083]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:40,998 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:40,999 INFO  [4571b2e9-cad0-416d-b601-f6df5de91068 HiveServer2-HttpHandler-Pool: Thread-6122]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:41,006 INFO  [HiveServer2-HttpHandler-Pool: Thread-6083]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:41,006 INFO  [4571b2e9-cad0-416d-b601-f6df5de91068 HiveServer2-HttpHandler-Pool: Thread-6083]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:41,032 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: service.CompositeService (:()) - Session closed, SessionHandle [4571b2e9-cad0-416d-b601-f6df5de91068], current sessions:2

                        2020-10-21T15:00:41,032 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:41,036 INFO  [4571b2e9-cad0-416d-b601-f6df5de91068 HiveServer2-HttpHandler-Pool: Thread-6122]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:41,036 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:41,037 INFO  [4571b2e9-cad0-416d-b601-f6df5de91068 HiveServer2-HttpHandler-Pool: Thread-6122]: session.HiveSessionImpl (:()) - Operation log session directory is deleted: /tmp/hive/operation_logs/4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:41,037 INFO  [4571b2e9-cad0-416d-b601-f6df5de91068 HiveServer2-HttpHandler-Pool: Thread-6122]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4571b2e9-cad0-416d-b601-f6df5de91068

                        2020-10-21T15:00:41,040 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: session.SessionState (:()) - Deleted directory: /tmp/hive/ambari-qa/4571b2e9-cad0-416d-b601-f6df5de91068 on fs with scheme hdfs

                        2020-10-21T15:00:41,040 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: session.SessionState (:()) - Deleted directory: /tmp/hive/4571b2e9-cad0-416d-b601-f6df5de91068 on fs with scheme file

                        2020-10-21T15:00:41,041 INFO  [HiveServer2-HttpHandler-Pool: Thread-6122]: metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore, current connections: 7

                         

                        Server 2-

                        2020-10-21T15:00:40,654 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: thrift.ThriftHttpServlet (:()) - Could not validate cookie sent, will try to generate a new cookie

                        2020-10-21T15:00:40,654 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: thrift.ThriftHttpServlet (:()) - Failed to authenticate with http/_HOST kerberos principal, trying with hive/_HOST kerberos principal

                        2020-10-21T15:00:40,655 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: thrift.ThriftHttpServlet (:()) - Cookie added for clientUserName ambari-qa

                        2020-10-21T15:00:40,655 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: thrift.ThriftCLIService (:()) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V10

                        2020-10-21T15:00:40,656 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI thrift://Hive2d:9083

                        2020-10-21T15:00:40,656 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.HiveMetaStoreClient (:()) - HMSC::open(): Could not find delegation token. Creating KERBEROS-based thrift connection.

                        2020-10-21T15:00:40,659 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore, current connections: 5

                        2020-10-21T15:00:40,659 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.HiveMetaStoreClient (:()) - Connected to metastore.

                        2020-10-21T15:00:40,659 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive/Hive1d@TESTAD.LOCAL (auth:KERBEROS) retries=24 delay=5 lifetime=0

                        2020-10-21T15:00:40,687 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: session.SessionState (:()) - Created HDFS directory: /tmp/hive/ambari-qa/0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,688 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: session.SessionState (:()) - Created local directory: /tmp/hive/0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,692 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: session.SessionState (:()) - Created HDFS directory: /tmp/hive/ambari-qa/0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581/_tmp_space.db

                        2020-10-21T15:00:40,693 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore, current connections: 4

                        2020-10-21T15:00:40,693 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI thrift://Hive1d:9083

                        2020-10-21T15:00:40,693 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.HiveMetaStoreClient (:()) - HMSC::open(): Found delegation token. Creating DIGEST-based thrift connection.

                        2020-10-21T15:00:40,695 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore, current connections: 5

                        2020-10-21T15:00:40,695 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.HiveMetaStoreClient (:()) - Connected to metastore.

                        2020-10-21T15:00:40,695 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=ambari-qa (auth:PROXY) via hive/Hive1d@TESTAD.LOCAL (auth:KERBEROS) retries=24 delay=5 lifetime=0

                        2020-10-21T15:00:40,862 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: session.HiveSessionImpl (:()) - Operation log session directory is created: /tmp/hive/operation_logs/0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,862 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: service.CompositeService (:()) - Session opened, SessionHandle [0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581], current sessions:2

                        2020-10-21T15:00:40,946 INFO  [HiveServer2-HttpHandler-Pool: Thread-6523]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,946 INFO  [0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581 HiveServer2-HttpHandler-Pool: Thread-6523]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,955 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,955 INFO  [0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581 HiveServer2-HttpHandler-Pool: Thread-6627]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,962 INFO  [HiveServer2-HttpHandler-Pool: Thread-6523]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,962 INFO  [0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581 HiveServer2-HttpHandler-Pool: Thread-6523]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,990 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: service.CompositeService (:()) - Session closed, SessionHandle [0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581], current sessions:1

                        2020-10-21T15:00:40,990 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,994 INFO  [0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581 HiveServer2-HttpHandler-Pool: Thread-6627]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,994 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,994 INFO  [0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581 HiveServer2-HttpHandler-Pool: Thread-6627]: session.HiveSessionImpl (:()) - Operation log session directory is deleted: /tmp/hive/operation_logs/0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,994 INFO  [0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581 HiveServer2-HttpHandler-Pool: Thread-6627]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581

                        2020-10-21T15:00:40,998 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: session.SessionState (:()) - Deleted directory: /tmp/hive/ambari-qa/0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581 on fs with scheme hdfs

                        2020-10-21T15:00:40,998 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: session.SessionState (:()) - Deleted directory: /tmp/hive/0b6a40c3-af7e-4f7c-a5a5-4c5801c4f581 on fs with scheme file

                        2020-10-21T15:00:40,998 INFO  [HiveServer2-HttpHandler-Pool: Thread-6627]: metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore, current connections: 4

                         

                         

                        Server 3-

                        2020-10-21T15:00:40,789 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: thrift.ThriftHttpServlet (:()) - Could not validate cookie sent, will try to generate a new cookie

                        2020-10-21T15:00:40,790 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: thrift.ThriftHttpServlet (:()) - Failed to authenticate with http/_HOST kerberos principal, trying with hive/_HOST kerberos principal

                        2020-10-21T15:00:40,790 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: thrift.ThriftHttpServlet (:()) - Cookie added for clientUserName ambari-qa

                        2020-10-21T15:00:40,790 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: thrift.ThriftCLIService (:()) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V10

                        2020-10-21T15:00:40,791 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI thrift://Hive1d:9083

                        2020-10-21T15:00:40,792 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.HiveMetaStoreClient (:()) - HMSC::open(): Could not find delegation token. Creating KERBEROS-based thrift connection.

                        2020-10-21T15:00:40,794 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore, current connections: 8

                        2020-10-21T15:00:40,794 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.HiveMetaStoreClient (:()) - Connected to metastore.

                        2020-10-21T15:00:40,794 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive/Hive0d@TESTAD.LOCAL (auth:KERBEROS) retries=24 delay=5 lifetime=0

                        2020-10-21T15:00:40,822 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: session.SessionState (:()) - Created HDFS directory: /tmp/hive/ambari-qa/ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:40,824 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: session.SessionState (:()) - Created local directory: /tmp/hive/ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:40,828 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: session.SessionState (:()) - Created HDFS directory: /tmp/hive/ambari-qa/ec00fcf2-55bc-4c12-83f4-ca61c917a0a8/_tmp_space.db

                        2020-10-21T15:00:40,828 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore, current connections: 7

                        2020-10-21T15:00:40,829 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI thrift://Hive2d:9083

                        2020-10-21T15:00:40,829 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.HiveMetaStoreClient (:()) - HMSC::open(): Found delegation token. Creating DIGEST-based thrift connection.

                        2020-10-21T15:00:40,831 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore, current connections: 8

                        2020-10-21T15:00:40,831 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.HiveMetaStoreClient (:()) - Connected to metastore.

                        2020-10-21T15:00:40,831 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=ambari-qa (auth:PROXY) via hive/Hive0d@TESTAD.LOCAL (auth:KERBEROS) retries=24 delay=5 lifetime=0

                        2020-10-21T15:00:40,990 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: session.HiveSessionImpl (:()) - Operation log session directory is created: /tmp/hive/operation_logs/ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:40,990 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: service.CompositeService (:()) - Session opened, SessionHandle [ec00fcf2-55bc-4c12-83f4-ca61c917a0a8], current sessions:3

                        2020-10-21T15:00:41,071 INFO  [HiveServer2-HttpHandler-Pool: Thread-8305]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,072 INFO  [ec00fcf2-55bc-4c12-83f4-ca61c917a0a8 HiveServer2-HttpHandler-Pool: Thread-8305]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,080 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,080 INFO  [ec00fcf2-55bc-4c12-83f4-ca61c917a0a8 HiveServer2-HttpHandler-Pool: Thread-8469]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,087 INFO  [HiveServer2-HttpHandler-Pool: Thread-8305]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,087 INFO  [ec00fcf2-55bc-4c12-83f4-ca61c917a0a8 HiveServer2-HttpHandler-Pool: Thread-8305]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,112 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: service.CompositeService (:()) - Session closed, SessionHandle [ec00fcf2-55bc-4c12-83f4-ca61c917a0a8], current sessions:2

                        2020-10-21T15:00:41,112 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,115 INFO  [ec00fcf2-55bc-4c12-83f4-ca61c917a0a8 HiveServer2-HttpHandler-Pool: Thread-8469]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,115 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,115 INFO  [ec00fcf2-55bc-4c12-83f4-ca61c917a0a8 HiveServer2-HttpHandler-Pool: Thread-8469]: session.HiveSessionImpl (:()) - Operation log session directory is deleted: /tmp/hive/operation_logs/ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,115 INFO  [ec00fcf2-55bc-4c12-83f4-ca61c917a0a8 HiveServer2-HttpHandler-Pool: Thread-8469]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: ec00fcf2-55bc-4c12-83f4-ca61c917a0a8

                        2020-10-21T15:00:41,119 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: session.SessionState (:()) - Deleted directory: /tmp/hive/ambari-qa/ec00fcf2-55bc-4c12-83f4-ca61c917a0a8 on fs with scheme hdfs

                        2020-10-21T15:00:41,119 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: session.SessionState (:()) - Deleted directory: /tmp/hive/ec00fcf2-55bc-4c12-83f4-ca61c917a0a8 on fs with scheme file

                        2020-10-21T15:00:41,119 INFO  [HiveServer2-HttpHandler-Pool: Thread-8469]: metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore, current connections: 7

                        • 9. Re: DEI writing to Hive with Kerberos
                          Prithvi Chaturvedi New Member

                          Hi Andrea,

                           

                          Are you specifying any LDAP username in the Hive Connection?

                          • 10. Re: DEI writing to Hive with Kerberos
                            Andrea Gruev Active Member

                            Greetings,

                             

                            No, we are using logged in user for creds passing.

                             

                            Regards,

                            Andrea G.

                            • 11. Re: DEI writing to Hive with Kerberos
                              Krishnan Sreekandath Seasoned Veteran

                              Hello Andrea,

                               

                              Thank you for the logs but I am afraid the mapping logs might be for a run where verbose initialization did not take effect and the HiveServer2 logs are off by about 36 seconds (mapping error was at 15:00:04 while the HS2 logs are for 15:00:40).

                               

                              Can you please tell me if you can rerun this again ?

                               

                              Thanks,

                              Krishnan

                              • 12. Re: DEI writing to Hive with Kerberos
                                Andrea Gruev Active Member

                                Greetings:

                                 

                                INFORMATICA LOG:

                                2020-10-26 11:21:32.662 <MappingCompiler-pool-4-thread-6> INFO: [MPSVCCMN_10083] The Mapping Service Module submitted a job to the Integration Service.  Job ID : [BOXl5xd1EeuEL2lJL52qVA]

                                2020-10-26 11:21:32.667 <MappingCompiler-pool-4-thread-6> FINE: [MPSVCCMN_10025] The Mapping Service Module [MappingService] started the LDTM create instance on the transformation machine BIm8Ihd1EeuEL2lJL52qVA.

                                2020-10-26 11:21:32.677 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [INFA_INTERNAL_MAPPING_PREVIEW_EXECUTION]=[true].

                                2020-10-26 11:21:32.681 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [StandAloneDTM]=[Yes].

                                2020-10-26 11:21:32.685 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [DataMovementMode]=[UNICODE].

                                2020-10-26 11:21:32.689 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [PMUser]=[Administrator].

                                2020-10-26 11:21:32.693 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [PMPassword]=[].

                                2020-10-26 11:21:32.698 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMRootDir]=[.].

                                2020-10-26 11:21:32.702 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMSourceFileDir]=[/appl/nas/informatica/TRANSFER/dis_shared_dir/source].

                                2020-10-26 11:21:32.707 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMTargetFileDir]=[/appl/nas/informatica/TRANSFER/dis_shared_dir/target].

                                2020-10-26 11:21:32.712 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMBadFileDir]=[/appl/nas/informatica/TRANSFER/dis_shared_dir/reject].

                                2020-10-26 11:21:32.716 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMCacheDir]=[/appl/nas/informatica/TRANSFER/dis_shared_dir/cache].

                                2020-10-26 11:21:32.721 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMTempDir]=[/appl/nas/informatica/TRANSFER/dis_shared_dir/disTemp].

                                2020-10-26 11:21:32.726 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMLookupFileDir]=[.].

                                2020-10-26 11:21:32.729 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMExtProcDir]=[].

                                2020-10-26 11:21:32.733 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMSessionLogDir]=[.].

                                2020-10-26 11:21:32.737 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMWorkflowLogDir]=[$PMRootDir/WorkflowLogs].

                                2020-10-26 11:21:32.741 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMStorageDir]=[$PMRootDir/Storage].

                                2020-10-26 11:21:32.745 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMSuccessEmailUser]=[dummy@informatica.com].

                                2020-10-26 11:21:32.749 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMFailureEmailUser]=[dummy@informatica.com].

                                2020-10-26 11:21:32.753 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMSessionLogCount]=[0].

                                2020-10-26 11:21:32.757 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMSessionErrorThreshold]=[0].

                                2020-10-26 11:21:32.761 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$PMWorkflowLogCount]=[0].

                                2020-10-26 11:21:32.766 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [PluginName]=[Mock].

                                2020-10-26 11:21:32.770 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [PluginId]=[202000].

                                2020-10-26 11:21:32.774 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [MinProcessPort]=[2000].

                                2020-10-26 11:21:32.778 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [MaxProcessPort]=[40000].

                                2020-10-26 11:21:32.782 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [ValidateDataCodePages]=[No].

                                2020-10-26 11:21:32.786 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [SessionLogInUTF8]=[No].

                                2020-10-26 11:21:32.789 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [ErrorSeverityLevel]=[Info].

                                2020-10-26 11:21:32.793 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [DateDisplayFormat]=[DY MON DD HH24:MI:SS YYYY].

                                2020-10-26 11:21:32.797 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [TreatNullInComparisonOperatorsAs]=[].

                                2020-10-26 11:21:32.801 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [CreateIndicatorFiles]=[No].

                                2020-10-26 11:21:32.805 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [NumOfDeadlockRetries]=[10].

                                2020-10-26 11:21:32.808 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [DeadlockSleep]=[0].

                                2020-10-26 11:21:32.813 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [RunInDebugMode]=[Yes].

                                2020-10-26 11:21:32.817 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [FlatFileInvalidNumberAsZero]=[Yes].

                                2020-10-26 11:21:32.822 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [TreatCHARasCHARonRead]=[Yes].

                                2020-10-26 11:21:32.826 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [SessionLogDateFormat]=[yyyy-MM-dd HH:mm:ss.SSS].

                                2020-10-26 11:21:32.830 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [LkupRemoveOrderBy]=[Yes].

                                2020-10-26 11:21:32.834 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [lookupOverrideParsingSetting]=[-1].

                                2020-10-26 11:21:32.838 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [ThreadPoolSize]=[16].

                                2020-10-26 11:21:32.842 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [HttpProxyServerOptions.HttpProxyServerPassword]=[].

                                2020-10-26 11:21:32.846 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.LicenseKey]=[].

                                2020-10-26 11:21:32.849 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.MaxResultCount]=[100].

                                2020-10-26 11:21:32.853 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [NODE_ADDRESS]=[//dis1.infa:6006].

                                2020-10-26 11:21:32.856 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.ReportLocation]=[.].

                                2020-10-26 11:21:32.860 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [IdentityOptions.IdentityCacheDir]=[].

                                2020-10-26 11:21:32.864 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.NoPreLoadCountries]=[ALL].

                                2020-10-26 11:21:32.868 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [HadoopStagingDir]=[/tmp].

                                2020-10-26 11:21:32.872 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [EnableConnectionPooling]=[Yes].

                                2020-10-26 11:21:32.876 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.FullPreLoadCountries]=[].

                                2020-10-26 11:21:32.880 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.NoPreLoadAddressCodeCountries]=[ALL].

                                2020-10-26 11:21:32.884 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [QASOptions.LicenseKeys]=[].

                                2020-10-26 11:21:32.888 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.NoPreLoadSuggestionListCountries]=[ALL].

                                2020-10-26 11:21:32.892 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [SERVICE_NAME]=[DIS_TEST].

                                2020-10-26 11:21:32.895 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.PartialPreLoadGeoCodingCountries]=[].

                                2020-10-26 11:21:32.899 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.PartialPreLoadCountries]=[].

                                2020-10-26 11:21:32.902 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [HttpProxyServerOptions.HttpProxyServerHost]=[].

                                2020-10-26 11:21:32.906 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.FullPreLoadGeoCodingCountries]=[].

                                2020-10-26 11:21:32.910 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [QASOptions.LogFile]=[./qas.log].

                                2020-10-26 11:21:32.914 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.ReferenceDataLocation]=[].

                                2020-10-26 11:21:32.917 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.MaxThreadCount]=[2].

                                2020-10-26 11:21:32.921 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [HttpProxyServerOptions.HttpProxyServerPort]=[8080].

                                2020-10-26 11:21:32.925 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.CacheSize]=[LARGE].

                                2020-10-26 11:21:32.928 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [NODE_NAME]=[node01].

                                2020-10-26 11:21:32.932 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [ServiceLogLevel]=[DEBUG].

                                2020-10-26 11:21:32.936 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [QASOptions.QawserveIni]=[].

                                2020-10-26 11:21:32.939 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [infapdo.dis.informatica.home]=[/appl/opt/infa].

                                2020-10-26 11:21:32.943 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [$DISAllTempDirs]=[/appl/opt/infa/tomcat/bin/disTemp].

                                2020-10-26 11:21:32.947 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.FullPreLoadSuggestionListCountries]=[].

                                2020-10-26 11:21:32.950 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [CreateDirectoryIfNotExists]=[YES].

                                2020-10-26 11:21:32.954 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [DISPrincipal]=[t_svc_idi_service@TESTAD.LOCAL].

                                2020-10-26 11:21:32.959 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [IdentityOptions.IdentityReferenceDataLocation]=[].

                                2020-10-26 11:21:32.963 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.PartialPreLoadAddressCodeCountries]=[].

                                2020-10-26 11:21:32.967 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.MemoryUsage]=[4096].

                                2020-10-26 11:21:32.971 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [GRID_NAME]=[grid_test].

                                2020-10-26 11:21:32.975 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [EnableLogService]=[false].

                                2020-10-26 11:21:32.979 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [NLPOptions.NERFileLocation]=[./ner].

                                2020-10-26 11:21:32.982 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [IdentityOptions.IdentityIndexDir]=[].

                                2020-10-26 11:21:32.986 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [EnableConnectionPoolingForPrePostSQL]=[No].

                                2020-10-26 11:21:32.990 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [NLPOptions.ClassifierFileLocation]=[./classifier].

                                2020-10-26 11:21:32.993 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [infapdo.hadoop.autoinstall.hdfsroot]=[/tmp].

                                2020-10-26 11:21:32.997 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [HttpProxyServerOptions.HttpProxyServerDomain]=[].

                                2020-10-26 11:21:33.001 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [infapdo.dis.hadoop.dir]=[/appl/opt/infa/services/shared/hadoop].

                                2020-10-26 11:21:33.005 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.NoPreLoadGeoCodingCountries]=[ALL].

                                2020-10-26 11:21:33.008 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [QASOptions.Cache]=[0].

                                2020-10-26 11:21:33.011 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [QASOptions.TimeOut]=[5000].

                                2020-10-26 11:21:33.014 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [DOMAIN_NAME]=[infa_test].

                                2020-10-26 11:21:33.017 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.FullPreLoadAddressCodeCountries]=[].

                                2020-10-26 11:21:33.020 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [DISKeytabLocation]=[/appl/opt/infa/services/shared/security/t_svc_idi_service.keytab].

                                2020-10-26 11:21:33.024 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.MaxAddressObjectCount]=[3].

                                2020-10-26 11:21:33.027 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [HttpProxyServerOptions.HttpProxyServerUser]=[].

                                2020-10-26 11:21:33.031 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [CREDENTIAL]=[***.

                                2020-10-26 11:21:33.036 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.PreloadingMethod]=[MAP].

                                2020-10-26 11:21:33.040 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [AddressManagerOptions.PartialPreLoadSuggestionListCountries]=[].

                                2020-10-26 11:21:33.043 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [BigDataJobRecovery]=[false].

                                2020-10-26 11:21:33.047 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6058] Using custom property [MappingJobId]=[BOXl5xd1EeuEL2lJL52qVA].

                                2020-10-26 11:21:33.050 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_4806] The mapping is being executed with operating system profile [Idip_Service_Profile].

                                2020-10-26 11:21:33.055 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/appl/nas/informatica/TRANSFER/dis_shared_dir/reject] for the system parameter [RejectDir].

                                2020-10-26 11:21:33.059 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/tmp] for the system parameter [StateStore].

                                2020-10-26 11:21:33.063 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/appl/nas/informatica/TRANSFER/dis_shared_dir/cache] for the system parameter [CacheDir].

                                2020-10-26 11:21:33.067 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/appl/nas/informatica/TRANSFER/dis_shared_dir/disTemp] for the system parameter [TempDir].

                                2020-10-26 11:21:33.071 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/appl/nas/informatica/TRANSFER/dis_shared_dir/target] for the system parameter [TargetDir].

                                2020-10-26 11:21:33.074 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [DIS_TEST] for the system parameter [ServiceName].

                                2020-10-26 11:21:33.078 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [/appl/nas/informatica/TRANSFER/dis_shared_dir/source] for the system parameter [SourceDir].

                                2020-10-26 11:21:33.094 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [Preview] for the system parameter [ApplicationName].

                                2020-10-26 11:21:33.098 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [testad.local\t_gruevan] for the system parameter [UserName].

                                2020-10-26 11:21:33.102 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [test_infa1] for the system parameter [MappingName].

                                2020-10-26 11:21:33.106 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [10/26/2020 11:21:32] for the system parameter [MappingRunStartTime].

                                2020-10-26 11:21:33.110 <MappingCompiler-pool-4-thread-6> INFO: [LDTMPARAM_0013] The Integration Service uses the value [native] for the system parameter [ExecutionEnvironment].

                                2020-10-26 11:21:33.123 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0117] Choose mapping execution engine [Native engine].

                                2020-10-26 11:21:33.128 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0026] LDTM: Starting mapping compilation.

                                2020-10-26 11:21:33.132 <MappingCompiler-pool-4-thread-6> FINEST: Encountered test_infa1

                                2020-10-26 11:21:33.137 <MappingCompiler-pool-4-thread-6> INFO: [LDTMCMN_0037] The Hadoop distribution directory is defined in Data Integration Service properties at the path [/appl/opt/infa/services/shared/hadoop/HDP_3.1.5].

                                2020-10-26 11:21:33.143 <MappingCompiler-pool-4-thread-6> INFO: [CLUSTERCONF_10024] The cluster configuration [BigData_Sandbox] is unchanged from the last export. Using the existing export file [/appl/nas/informatica/TRANSFER/dis_shared_dir/disTemp/infa_test/DIS_TEST/node01/bigdata_sandbox/NATIVE/e4114dfc-901e-4359-ba0a-e2fc5235f2f5/infacco-site.xml].

                                2020-10-26 11:21:33.147 <MappingCompiler-pool-4-thread-6> INFO: [CLUSTERCONF_10028] Based on the distribution [HORTONWORKS] and the run-time engine [NATIVE], the Data Integration Service will override the following cluster configuration properties at run time: null

                                2020-10-26 11:21:33.152 <MappingCompiler-pool-4-thread-6> FINEST: Encountered OutputParameters

                                2020-10-26 11:21:33.157 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0027] LDTM: Mapping compilation done.

                                2020-10-26 11:21:33.208 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0035] LDTM: Starting mapping translation.

                                2020-10-26 11:21:33.213 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0036] LDTM: Mapping translation finished.

                                2020-10-26 11:21:33.217 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_4600] LDTM: Detecting the data movement mode for the mapping.

                                2020-10-26 11:21:33.221 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_4601] LDTM: Setting the data movement mode for the mapping to [UNICODE].

                                2020-10-26 11:21:33.225 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_1202] LDTM: Starting mapping simplification.

                                2020-10-26 11:21:33.230 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_1203] LDTM: Mapping simplification complete.

                                2020-10-26 11:21:33.234 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0028] LDTM: Optimizing mapping...

                                2020-10-26 11:21:33.239 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0600] The optimizer will use the following configuration:

                                Optimizer.IgnoreOrderOfOp: true

                                Optimizer.IgnoreOrderOfImplicitDataConv: true

                                DTM.DateFormat: MM/DD/YYYY HH24:MI:SS

                                DTM.HighPrecisionEnabled: true

                                DTM.LookupParseOverride: false

                                Optimizer.TreatOutputFieldErrorAsSideEffect: false

                                DTM.TreatNullInComparisonOperatorsAs: NULL

                                Optimizer.EnableEarlyUncorrelatedSubquery: true

                                Optimizer.EnablePredicateInference: true

                                Optimizer.EnablePredicateMinimization: true

                                Optimizer.EnableEarlyProjection: true

                                Optimizer.EnableEarlySelection: true

                                Optimizer.EnableSemiJoin: false

                                Optimizer.EnableDatashipJoin: false

                                Optimizer.EnableCostBasedOptimization: false

                                Optimizer.EnableBranchPruning: true

                                DTM.CommitType: target

                                isAsciiMode: false

                                ReservedWordsFile: null

                                Optimizer.PdoEnabledToSources: false

                                Optimizer.PushdownType: none

                                2020-10-26 11:21:33.243 <MappingCompiler-pool-4-thread-6> FINE: Optimizer.GlobalPredicateOptimization: true

                                2020-10-26 11:21:33.246 <MappingCompiler-pool-4-thread-6> INFO: [OPT_1600] The Integration Service is extracting constraints from sources.

                                2020-10-26 11:21:33.251 <MappingCompiler-pool-4-thread-6> INFO: [OPT_1603] The Integration Service is extracting constraints from the source [test_infa1].

                                2020-10-26 11:21:33.255 <MappingCompiler-pool-4-thread-6> FINE: [OPT_1614] The Integration Service did not extract any constraints for the source [test_infa1].

                                2020-10-26 11:21:33.260 <MappingCompiler-pool-4-thread-6> INFO: [OPT_1601] The Integration Service has finished extracting constraints from sources.

                                2020-10-26 11:21:33.266 <MappingCompiler-pool-4-thread-6> INFO: [OPT_1300] Running expression simplifier.

                                2020-10-26 11:21:33.270 <MappingCompiler-pool-4-thread-6> INFO: Starting early uncorrelated subquery optimization.

                                2020-10-26 11:21:33.273 <MappingCompiler-pool-4-thread-6> INFO: Early uncorrelated subquery optimization is finished.

                                2020-10-26 11:21:33.276 <MappingCompiler-pool-4-thread-6> INFO: [OPT_1700] The Integration Service is starting the Global Predicate Optimization method.

                                2020-10-26 11:21:33.287 <MappingCompiler-pool-4-thread-6> INFO: [OPT_1701] The Integration Service has finished applying the Global Predicate Optimization method.

                                2020-10-26 11:21:33.291 <MappingCompiler-pool-4-thread-6> INFO: [OPT_0500] Predicate optimization is starting.

                                2020-10-26 11:21:33.295 <MappingCompiler-pool-4-thread-6> INFO: [OPT_0501] Predicate optimization is finished.

                                2020-10-26 11:21:33.301 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0346] The Integration Service is skipping early selection predicate inference optimization because there are no Filter transformations found after the last Joiner transformation in the mapping.

                                2020-10-26 11:21:33.305 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0336] The Integration Service cannot apply early selection joiner optimization to the mapping because the mapping does not include a Joiner transformation.

                                2020-10-26 11:21:33.308 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0301] Early selection optimization was skipped because the mapping does not contain any Filter transformation.

                                2020-10-26 11:21:33.313 <MappingCompiler-pool-4-thread-6> INFO: Predicate minimization is starting.

                                2020-10-26 11:21:33.316 <MappingCompiler-pool-4-thread-6> INFO: Predicate minimization is finished.

                                2020-10-26 11:21:33.319 <MappingCompiler-pool-4-thread-6> INFO: [OPT_1300] Running expression simplifier.

                                2020-10-26 11:21:33.323 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0375] The Integration Service is starting a limited pass to move expressions as part of predicate optimization.

                                2020-10-26 11:21:33.326 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0377] The Integration Service has finished a limited pass to move expressions as part of predicate optimization.

                                2020-10-26 11:21:33.330 <MappingCompiler-pool-4-thread-6> INFO: [OPT_0008] Early projection optimization is starting.

                                2020-10-26 11:21:33.334 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0001] The early projection detection phase is starting.

                                2020-10-26 11:21:33.338 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0010] The early projection detection phase is finished.

                                2020-10-26 11:21:33.342 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0002] The early projection application phase is starting.

                                2020-10-26 11:21:33.346 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0020] The early projection application phase is finished.

                                2020-10-26 11:21:33.351 <MappingCompiler-pool-4-thread-6> INFO: [OPT_0009] Early projection optimization is finished.

                                2020-10-26 11:21:33.355 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0376] The Integration Service is starting a full pass to move expressions as part of predicate optimization.

                                2020-10-26 11:21:33.359 <MappingCompiler-pool-4-thread-6> FINE: [OPT_0378] The Integration Service has finished a full pass to move expressions as part of predicate optimization.

                                2020-10-26 11:21:33.362 <MappingCompiler-pool-4-thread-6> INFO: [OPT_1400] The integration service is pruning the mapping.

                                2020-10-26 11:21:33.366 <MappingCompiler-pool-4-thread-6> FINE: [OPT_1404] The branch pruning optimization will maintain dependencies between transformations.

                                2020-10-26 11:21:33.370 <MappingCompiler-pool-4-thread-6> FINE: [OPT_1407] The branch pruning optimization is starting a reconfiguration step.

                                2020-10-26 11:21:33.374 <MappingCompiler-pool-4-thread-6> FINE: [OPT_1408] The branch pruning optimization has finished a reconfiguration step.

                                2020-10-26 11:21:33.377 <MappingCompiler-pool-4-thread-6> FINE: [OPT_1405] The branch pruning optimization is starting the deletion step.

                                2020-10-26 11:21:33.381 <MappingCompiler-pool-4-thread-6> FINE: [OPT_1406] The branch pruning optimization has finished the deletion step.

                                2020-10-26 11:21:33.386 <MappingCompiler-pool-4-thread-6> FINE: [OPT_1407] The branch pruning optimization is starting a reconfiguration step.

                                2020-10-26 11:21:33.390 <MappingCompiler-pool-4-thread-6> FINE: [OPT_1408] The branch pruning optimization has finished a reconfiguration step.

                                2020-10-26 11:21:33.393 <MappingCompiler-pool-4-thread-6> INFO: [OPT_1401] The integration service has finished pruning the mapping.

                                2020-10-26 11:21:33.397 <MappingCompiler-pool-4-thread-6> INFO: [OPT_63306] Pushdown optimization is not enabled for this mapping.

                                2020-10-26 11:21:33.401 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0029] LDTM: Mapping optimization done.

                                2020-10-26 11:21:33.405 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0038] LDTM: Starting operations on data sources after optimization.

                                2020-10-26 11:21:33.408 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0039] LDTM: Post-optimization tasks for operations on data sources are complete.

                                2020-10-26 11:21:33.413 <MappingCompiler-pool-4-thread-6> INFO: [OPT_1900] Native Expression transformation optimization is starting.

                                2020-10-26 11:21:33.417 <MappingCompiler-pool-4-thread-6> FINE: [LDTM_2012] Auto Partitioning is cloning the mapping.

                                2020-10-26 11:21:33.423 <MappingCompiler-pool-4-thread-6> FINEST: The compiled mapping test_infa1 has 2 transformations.

                                2020-10-26 11:21:33.427 <MappingCompiler-pool-4-thread-6> INFO: Partitioner running in preview mode.

                                 

                                2020-10-26 11:21:33.442 <MappingCompiler-pool-4-thread-6> INFO: Cardinality coefficient per partition: 10000

                                2020-10-26 11:21:33.446 <MappingCompiler-pool-4-thread-6> INFO: AutoPartitionResult {

                                    GlobalMaxPartitions: 1

                                    TxPartitionInfo {

                                        Instance: test_infa1

                                        MaxPartitions: 1

                                        IdealMaxPartitions: 1

                                        IsPartitionPoint: true

                                        IsOnForcedPartitionPath: false

                                        GroupOrdering: O

                                        TxPartitionGroupInfo {

                                            Interface: test_infa1

                                            DataPartitionScheme {

                                                Interface: test_infa1

                                                PartitionScheme: ArbitraryPartitioning

                                                MergeScheme: DefaultMerge

                                            }

                                            PartitioningPointScheme {

                                                Interface: test_infa1

                                                PartitionScheme: PassthroughPartitioning

                                                MergeScheme: DefaultMerge

                                            }

                                            IsInput: true

                                            MergeSPMLocator: NA

                                            Ords: {}

                                            ExtrapolatedRowCount: -1

                                            ExtrapolatedVolume: 0

                                        }

                                        TxPartitionGroupInfo {

                                            Interface: test_infa1

                                            DataPartitionScheme {

                                                Interface: test_infa1

                                                PartitionScheme: ArbitraryPartitioning

                                                MergeScheme: DefaultMerge

                                            }

                                            IsInput: false

                                            MergeSPMLocator: NA

                                            Ords: NA

                                            ExtrapolatedRowCount: 1

                                            ExtrapolatedVolume: 10

                                        }

                                    }

                                }

                                 

                                2020-10-26 11:21:33.450 <MappingCompiler-pool-4-thread-6> INFO: Partitioning is enabled for the mapping.

                                2020-10-26 11:21:33.454 <MappingCompiler-pool-4-thread-6> INFO: Maximum parallelism is 1.

                                2020-10-26 11:21:33.457 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_1204] LDTM: Starting mapping simplification clean up.

                                2020-10-26 11:21:33.461 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_1205] LDTM: Mapping simplification clean up complete.

                                2020-10-26 11:21:33.467 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0030] LDTM: Preparing to execute the mapping.

                                2020-10-26 11:21:33.472 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6068] Informatica os name is [Linux] and version is [3.10.0-1062.el7.x86_64].

                                2020-10-26 11:21:33.476 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6069] Informatica user name is [idip].

                                2020-10-26 11:21:33.480 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_6070] Service Principal name is [t_svc_idi_service@TESTAD.LOCAL].

                                2020-10-26 11:21:33.484 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_7009] Following properties have values different than their default values. Effective values for these properties are as follows:

                                  - INFA_INTERNAL_MAPPING_PREVIEW_EXECUTION: true

                                  - CreateDirectoryIfNotExists: YES

                                  - EnableConnectionPooling: Yes

                                  - EnableConnectionPoolingForPrePostSQL: No

                                  - DataMovementMode: UNICODE

                                2020-10-26 11:21:33.487 <MappingCompiler-pool-4-thread-6> INFO: [LDTM_0074] Total time to create the LDTM: 811 ms

                                2020-10-26 11:21:33.500 <MappingCompiler-pool-4-thread-6> INFO: [DS_10178] The job is running on Integration Service [DIS_TEST]. The Launch Job Options for the service is set to: [In separate local processes (OUT_OF_PROCESS)].

                                2020-10-26 11:21:33.504 <MappingCompiler-pool-4-thread-6> INFO: [ExecsCmn_00008] LDTM Output Stream is encoded in [Fast Infoset] format.

                                2020-10-26 11:21:33.812 <APP_OnDemandDTM-pool-2-thread-18> INFO: [JDTM_10055] The Integration Service is dispatching the job with operating system profile [Idip_Service_Profile] to the DTM process [DTMProcess_9].

                                2020-10-26 11:21:33.932 <APP_140714184791808> INFO: [TM_6982] DTM resource allocation policy: [OnDemand]; Time slice: [0] milliseconds; Data slice: [0] KB.

                                2020-10-26 11:21:33.937 <APP_OnDemandDTM-pool-2-thread-18> FINER: [JDTM_10032] Data Exchange running in streaming mode.

                                2020-10-26 11:21:33.941 <APP_140714184791808> INFO: [VAR_27079] Warning: server variable :[$PMExtProcDir], NULL override value not valid. The override value is set to empty string.

                                2020-10-26 11:21:33.947 <APP_140714184791808> INFO: [VAR_27092] Warning! Found an unused name and value pair [$DISAllTempDirs = /appl/opt/infa/tomcat/bin/disTemp].

                                2020-10-26 11:21:33.953 <APP_140714184791808> FINE: [VAR_27028] Use override value [/appl/nas/informatica/TRANSFER/dis_shared_dir/reject] for server variable:[$PMBadFileDir].

                                2020-10-26 11:21:33.957 <APP_140714184791808> FINE: [VAR_27028] Use override value [/appl/nas/informatica/TRANSFER/dis_shared_dir/cache] for server variable:[$PMCacheDir].

                                2020-10-26 11:21:33.961 <APP_140714184791808> FINE: [VAR_27028] Use override value [dummy@informatica.com] for server variable:[$PMFailureEmailUser].

                                2020-10-26 11:21:33.965 <APP_140714184791808> FINE: [VAR_27028] Use override value [.] for server variable:[$PMLookupFileDir].

                                2020-10-26 11:21:33.969 <APP_140714184791808> FINE: [VAR_27028] Use override value [.] for server variable:[$PMRootDir].

                                2020-10-26 11:21:33.974 <APP_140714184791808> FINE: [VAR_27028] Use override value [0] for server variable:[$PMSessionErrorThreshold].

                                2020-10-26 11:21:33.979 <APP_140714184791808> FINE: [VAR_27028] Use override value [0] for server variable:[$PMSessionLogCount].

                                2020-10-26 11:21:33.983 <APP_140714184791808> FINE: [VAR_27028] Use override value [.] for server variable:[$PMSessionLogDir].

                                2020-10-26 11:21:33.987 <APP_140714184791808> FINE: [VAR_27028] Use override value [/appl/nas/informatica/TRANSFER/dis_shared_dir/source] for server variable:[$PMSourceFileDir].

                                2020-10-26 11:21:33.992 <APP_140714184791808> FINE: [VAR_27028] Use override value [$PMRootDir/Storage] for server variable:[$PMStorageDir].

                                2020-10-26 11:21:33.995 <APP_140714184791808> FINE: [VAR_27028] Use override value [dummy@informatica.com] for server variable:[$PMSuccessEmailUser].

                                2020-10-26 11:21:33.999 <APP_140714184791808> FINE: [VAR_27028] Use override value [/appl/nas/informatica/TRANSFER/dis_shared_dir/target] for server variable:[$PMTargetFileDir].

                                2020-10-26 11:21:34.002 <APP_140714184791808> FINE: [VAR_27028] Use override value [/appl/nas/informatica/TRANSFER/dis_shared_dir/disTemp] for server variable:[$PMTempDir].

                                2020-10-26 11:21:34.006 <APP_140714184791808> FINE: [VAR_27028] Use override value [0] for server variable:[$PMWorkflowLogCount].

                                2020-10-26 11:21:34.011 <APP_140714184791808> FINE: [VAR_27028] Use override value [$PMRootDir/WorkflowLogs] for server variable:[$PMWorkflowLogDir].

                                2020-10-26 11:21:34.015 <APP_140714184791808> INFO: [DISP_20305] The [Master] DTM with process id [20149] is running on node [node01].

                                 

                                2020-10-26 11:21:34.019 <APP_140714184791808> INFO: [TM_6964] Date format for the Session is [MM/DD/YYYY HH24:MI:SS]

                                2020-10-26 11:21:34.023 <APP_140714184791808> INFO: [TM_6983] Size of the thread pool that the DTM uses to allocate CPU resources: [16].

                                2020-10-26 11:21:34.027 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.RejectDir=/appl/nas/informatica/TRANSFER/dis_shared_dir/reject].

                                2020-10-26 11:21:34.031 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.StateStore=/tmp].

                                2020-10-26 11:21:34.036 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.CacheDir=/appl/nas/informatica/TRANSFER/dis_shared_dir/cache].

                                2020-10-26 11:21:34.039 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.TempDir=/appl/nas/informatica/TRANSFER/dis_shared_dir/disTemp].

                                2020-10-26 11:21:34.043 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.TargetDir=/appl/nas/informatica/TRANSFER/dis_shared_dir/target].

                                2020-10-26 11:21:34.047 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.ServiceName=DIS_TEST].

                                2020-10-26 11:21:34.051 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.SourceDir=/appl/nas/informatica/TRANSFER/dis_shared_dir/source].

                                2020-10-26 11:21:34.055 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.ApplicationName=Preview].

                                2020-10-26 11:21:34.058 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.UserName=testad.local\t_gruevan].

                                2020-10-26 11:21:34.062 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.MappingName=test_infa1].

                                2020-10-26 11:21:34.067 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.MappingRunStartTime=10/26/2020 11:21:32].

                                2020-10-26 11:21:34.071 <APP_140714176399104> FINE: [VAR_27128] Received Parameter Binding : [SYS.ExecutionEnvironment=native].

                                2020-10-26 11:21:34.075 <APP_140714135308032> INFO: [TM_6721] Started [Partition Group Formation].

                                2020-10-26 11:21:34.079 <APP_140714135308032> INFO: [TM_6722] Finished [Partition Group Formation].  It took [0.000656128] seconds.

                                2020-10-26 11:21:34.083 <APP_140714135308032> INFO: [TM_6014] Initializing session [test_infa1] at [Mon Oct 26 11:21:33 2020].

                                2020-10-26 11:21:34.088 <APP_140714135308032> INFO: [TM_6101] Mapping name: test_infa1.

                                2020-10-26 11:21:34.094 <APP_140714135308032> INFO: [TM_6348] The maximum number of files that can be open at a time is 65535.

                                2020-10-26 11:21:34.100 <APP_140714135308032> INFO: [TM_6708] Using configuration property [EnableConnectionPooling,Yes]

                                2020-10-26 11:21:34.105 <APP_140714135308032> INFO: [TM_6708] Using configuration property [EnableConnectionPoolingForPrePostSQL,No]

                                2020-10-26 11:21:34.109 <APP_140714135308032> INFO: [TM_6708] Using configuration property [LkupRemoveOrderBy,Yes]

                                2020-10-26 11:21:34.114 <APP_140714135308032> INFO: [TM_6708] Using configuration property [CreateDirectoryIfNotExists,YES]

                                2020-10-26 11:21:34.119 <APP_140714135308032> INFO: [TM_6708] Using configuration property [lookupOverrideParsingSetting,-1]

                                2020-10-26 11:21:34.123 <APP_140714135308032> INFO: [TM_6703] Session [test_infa1] is run by 64-bit Data Integration Service  [DIS_TEST], version [10.4.1], build [195].

                                2020-10-26 11:21:34.128 <TASK_140713631135488-MAPPING> INFO: [PETL_24000] Parallel Pipeline Engine initializing.

                                2020-10-26 11:21:34.132 <TASK_140713631135488-MAPPING> INFO: [PETL_24001] Parallel Pipeline Engine running.

                                2020-10-26 11:21:34.136 <TASK_140713631135488-MAPPING> INFO: [CMN_1569] Server Mode: [UNICODE]

                                2020-10-26 11:21:34.141 <TASK_140713631135488-MAPPING> INFO: [CMN_1570] Server Code page: [UTF-8 encoding of Unicode]

                                2020-10-26 11:21:34.146 <TASK_140713631135488-MAPPING> INFO: [TM_6151] The session sort order is [Binary].

                                2020-10-26 11:21:34.150 <TASK_140713631135488-MAPPING> INFO: [TM_6185] Warning. Code page validation is disabled in this session.

                                2020-10-26 11:21:34.153 <TASK_140713631135488-MAPPING> INFO: [TM_6165] The error threshold value = [0].

                                2020-10-26 11:21:34.157 <TASK_140713631135488-MAPPING> INFO: [TM_6155] Using HIGH precision processing.

                                2020-10-26 11:21:34.161 <TASK_140713631135488-MAPPING> INFO: [TM_6179] Deadlock retry logic will be implemented.

                                2020-10-26 11:21:34.166 <TASK_140713631135488-MAPPING> INFO: [SDKS_38020] Plug-in [10000000] loaded successfully.

                                2020-10-26 11:21:34.170 <TASK_140713631135488-MAPPING> INFO: [SDKS_38021] Plug-in 10000000's interface version is compatible with the framework. Framework's interface version: [5.0.0]. Plug-in's interface version: [5.0.0].

                                2020-10-26 11:21:34.174 <TASK_140713631135488-MAPPING> INFO: [SDKS_38022] Plug-in 10000000's driver fetched successfully.

                                2020-10-26 11:21:34.178 <TASK_140713631135488-MAPPING> INFO: [SDKS_38023] Plug-in 10000000's [init] method invocation successful.

                                2020-10-26 11:21:34.182 <TASK_140713631135488-MAPPING> INFO: [SDKS_38023] Plug-in 10000000's [validate] method invocation successful.

                                2020-10-26 11:21:34.186 <TASK_140713631135488-MAPPING> INFO: [SDKS_38024] Plug-in 10000000 initialization complete.

                                2020-10-26 11:21:34.189 <TASK_140713631135488-MAPPING> INFO: [SDKS_38017] Writer SDK plug-in initialization complete.

                                2020-10-26 11:21:34.193 <TASK_140713631135488-MAPPING> INFO: [SDKS_38509] SDK target and group initialization complete.

                                2020-10-26 11:21:34.197 <TASK_140713631135488-MAPPING> INFO: [TM_6307] DTM error log disabled.

                                2020-10-26 11:21:34.200 <TASK_140713631135488-MAPPING> INFO: [TE_7022] TShmWriter: Initialized

                                2020-10-26 11:21:34.204 <TASK_140713631135488-MAPPING> INFO: [DBG_21245] Initializing Pre and Post Stored Procedures...

                                2020-10-26 11:21:34.208 <TASK_140713631135488-MAPPING> INFO: [DBG_21249] Initializing Transform: expr_OutputParameters_OUTPUT

                                2020-10-26 11:21:34.212 <TASK_140713631135488-MAPPING> INFO: [DBG_21371] Number of Input Transforms = [1]:

                                2020-10-26 11:21:34.215 <TASK_140713631135488-MAPPING> INFO: [DBG_21259]   Input Transform[0]: [test_infa1]

                                2020-10-26 11:21:34.219 <TASK_140713631135488-MAPPING> INFO: [DBG_21098] Default values: Input Row[0] from transform [test_infa1]

                                2020-10-26 11:21:34.223 <TASK_140713631135488-MAPPING> INFO: [DBG_21056]   column=[id], defaultvalue=[NULL]

                                2020-10-26 11:21:34.226 <TASK_140713631135488-MAPPING> INFO: [DBG_21375] Number of Output Transforms = [1]:

                                2020-10-26 11:21:34.230 <TASK_140713631135488-MAPPING> INFO: [DBG_21398]   Output Transform[0]: [Data_Exchange_Target-expr_OutputParameters_OUTPUT]

                                2020-10-26 11:21:34.234 <TASK_140713631135488-MAPPING> INFO: [DBG_21099] Default values: Output Row[0] going to transform [Data_Exchange_Target-expr_OutputParameters_OUTPUT]

                                2020-10-26 11:21:34.239 <TASK_140713631135488-MAPPING> INFO: [DBG_21249] Initializing Transform: Data_Exchange_Target-expr_OutputParameters_OUTPUT

                                2020-10-26 11:21:34.243 <TASK_140713631135488-MAPPING> INFO: [DBG_21371] Number of Input Transforms = [1]:

                                2020-10-26 11:21:34.247 <TASK_140713631135488-MAPPING> INFO: [DBG_21258]   Input Transform[0]: [expr_OutputParameters_OUTPUT]

                                2020-10-26 11:21:34.252 <TASK_140713631135488-MAPPING> INFO: [DBG_21372] Data_Exchange_Target-expr_OutputParameters_OUTPUT: Number of Input Transforms = [1]:

                                2020-10-26 11:21:34.257 <TASK_140713631135488-MAPPING> INFO: [DBG_21258]   Input Transform[0]: [expr_OutputParameters_OUTPUT]

                                2020-10-26 11:21:34.262 <TASK_140713631135488-MAPPING> INFO: [TM_6007] DTM initialized successfully for session [test_infa1]

                                2020-10-26 11:21:34.267 <TASK_140713631135488-MAPPING> INFO: [PETL_24003] Initializing session run.

                                2020-10-26 11:21:34.272 <TASK_140713631135488-PRE-SESS> INFO: [PETL_24004] Starting pre-session tasks.

                                2020-10-26 11:21:34.276 <TASK_140713631135488-PRE-SESS> INFO: [TM_6746] Ready to execute pre-session command.

                                2020-10-26 11:21:34.282 <TASK_140713631135488-PRE-SESS> INFO: [TM_6985] Ready to recreate target tables.

                                2020-10-26 11:21:34.287 <TASK_140713631135488-PRE-SESS> INFO: [TM_6747] Ready to truncate target tables.

                                2020-10-26 11:21:34.291 <TASK_140713631135488-PRE-SESS> INFO: [TM_6748] Ready to execute pre-session stored procedure.

                                2020-10-26 11:21:34.296 <TASK_140713631135488-PRE-SESS> INFO: [TM_6749] Pre-session stored procedure executed.

                                2020-10-26 11:21:34.300 <TASK_140713631135488-PRE-SESS> INFO: [PETL_24027] Pre-session task completed successfully.

                                2020-10-26 11:21:34.306 <TASK_140713631135488-MAPPING> INFO: [PETL_24006] Starting data movement.

                                2020-10-26 11:21:34.311 <TASK_140713631135488-MAPPING> INFO: [TM_6660] Total Buffer Pool size is 1179648 bytes and Block size is 65536 bytes.

                                2020-10-26 11:21:34.314 <TASK_140713631135488-MAPPING> INFO: [TM_6754] Pre SQL for source executed.

                                2020-10-26 11:21:34.318 <TASK_140713631135488-MAPPING> INFO: [TM_6755] Pre SQL for target executed.

                                2020-10-26 11:21:34.322 <TASK_140713631135488-MAPPING> INFO: [TM_6361] Pushdown setup SQL for source, if any, is executed.

                                2020-10-26 11:21:34.326 <TASK_140713631135488-MAPPING> INFO: [TM_6369] Pushdown setup SQL for target, if any, is executed.

                                2020-10-26 11:21:34.331 <TASK_140713622742784-READER_1_1_1> INFO: [DBG_21438] Reader: Source is [jdbc:zoo2://zoo1.internal:2181,zoo2.internal:2181,zoo3.internal:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;transportMode=http;httpPath=cliservice;principal=hive/_HOST@TESTAD.LOCAL], user []

                                2020-10-26 11:21:34.335 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26122] The Integration Service does not use a connection pool for connection [HIVE_bigdata_sandbox].

                                2020-10-26 11:21:34.339 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [

                                Error action file of type [Database] is set to file [NULL] for adapter [com.informatica.adapter.Hive.HiveConnectInfo].

                                Error action file of type [User] is set to file [NULL] for adapter [com.informatica.adapter.Hive.HiveConnectInfo].]

                                2020-10-26 11:21:34.343 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=Setting up handle type 2. Parent context owner is thread 1904191232]

                                2020-10-26 11:21:34.347 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=Allocated Connection handle OK]

                                2020-10-26 11:21:34.352 <TASK_140713622742784-READER_1_1_1> INFO: [BLKR_16051] Source database connection [HIVE_bigdata_sandbox] code page: [UTF-8 encoding of Unicode]

                                2020-10-26 11:21:34.356 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26098] Connecting to database [jdbc:zoo2://zoo1.internal:2181,zoo2.internal:2181,zoo3.internal:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;transportMode=http;httpPath=cliservice;principal=hive/_HOST@TESTAD.LOCAL]...

                                2020-10-26 11:21:34.360 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=Starting connect]

                                2020-10-26 11:21:34.363 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=Starting JVM]

                                2020-10-26 11:21:34.851 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=Java Adapter Loaded]

                                2020-10-26 11:21:34.858 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=00000; NativeError=0; Message=MSG Level = 31]

                                2020-10-26 11:21:34.863 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=00000; NativeError=0; Message=Connection attributes were passed to the adapter=49]

                                2020-10-26 11:21:34.869 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=Attempt Java Connection]

                                2020-10-26 11:21:34.875 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=]

                                2020-10-26 11:21:37.917 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=Classpath for connect=/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.repository.jrs.service.interface-10.4.1.8.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.imf.annotations-10.4.1.4.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.ilm.tx.handlers-10.4.1.63.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.dsg.encryption.tx.handlers-10.4.1.63.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.basemodel.common-metamodel.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.shapp.upgradehandlers.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.repository.jrs.models.capability.sample.repostats-10.4.1.8.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.designsdk.impl-10.4.1.6.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.at.at-ospoptions-10.4.1.27.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.extensions.transformation.r2soaptx.java-10.4.1.23.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/ispImpl-com.infa.products.isp.coreservices.implementationutils.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.ilm.tx.jdbcconnmanager-10.4.1.63.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.pwx.service.impl-10.4.1.1.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/ispInterface-com.infa.products.isp.coreservices.cloudservice.cloudservice.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.extensions.adapter.httpconnectinfo.semanticlayer-10.4.1.1.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.dtmsecurity.processlauncher-10.4.1.3.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.extensions.adapter.sdk.sdkplggen.util-10.4.1.23.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/ispInterface-com.infa.products.isp.coreservices.usermanagementservice.usermanagementservice.jar:/appl/opt/infa/services/shared/jars/platform/servicesframework-com.informatica.servicesframework.restclient.ics.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.repository.jrs.models.service.serviceprops-10.4.1.8.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.remotemetadataaccess.utils-10.4.1.3.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.pwx.loggerservice.plugin-10.4.1.1.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.basemodel.monitoring.java.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.repository.prs.deployer.embedded-10.4.1.8.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/cmnframeworks-com.infa.products.frameworks.statscollectorframework.statscollectorframeworkimpl.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.repository.persistence.models.database-10.4.1.8.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.imf.upgrade.interface-10.4.1.4.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/base-component-com.infa.products.extensions.extensionsloader.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.extensions.adapter.sap.common.models.sapconnectinfo.java-10.4.1.9.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.extensions.adapter.nonrel.pwxnrdb-pm.java-10.4.1.8.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.dtm.cal.cal-hadoop.jar:/appl/opt/infa/services/shared/jars/platform/ispImpl-com.infa.products.isp.pcsf.common.jar:/appl/opt/infa/services/shared/jars/platform/cmnframeworks-com.infa.products.frameworks.logging.slf4j.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.basemodel.mapping_comp.dynamic.interface.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.b2b_dt.tx.hdp_to_dt_util.jar:/appl/opt/infa/services/shared/jars/platform/ispInterface-com.infa.products.isp.coreservices.logserviceagent.logserviceagent.jar:/appl/opt/infa/services/shared/jars/platform/ispInterface-com.infa.products.isp.coreservices.domainconfigurationservice.domainconfigurationservice.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.extensions.transformation.hivebucketingtx.java-10.4.1.23.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.repository.infrastructure.service.impl-10.4.1.8.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.repository.jrs.client.impl-10.4.1.8.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa.products.extensions.adapter.rel.hive.runtime.HiveJDBCAdapter-10.4.1.10.195-SNAPSHOT.jar:/appl/opt/infa/services/shared/jars/platform/com.infa-com.infa.products.sched]

                                2020-10-26 11:21:37.923 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=]

                                2020-10-26 11:21:37.930 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=]

                                2020-10-26 11:21:37.934 <OnDemandDTM-pool-2-thread-18> SEVERE: [EdtmExec_00007] RR_4036 Error connecting to database [

                                Function [INFASQLConnectW] failed in adapter [/appl/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

                                 

                                Database driver error...

                                Function Name : Connect

                                Database driver error...

                                Function Name : Connect

                                Database Error: Failed to connect to database using user [] and connection string [jdbc:zoo2://zoo1.internal:2181,zoo2.internal:2181,zoo3.internal:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;transportMode=http;httpPath=cliservice;principal=hive/_HOST@TESTAD.LOCAL].].

                                2020-10-26 11:21:37.936 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=]

                                2020-10-26 11:21:37.949 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=]

                                2020-10-26 11:21:37.953 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26130] Database informational message encountered in connection object [HIVE_bigdata_sandbox]: [Adapter=com.informatica.adapter.Hive.HiveConnectInfo; SQLState=000000; NativeError=0; Message=]

                                2020-10-26 11:21:37.957 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26104] Cannot connect to database [jdbc:zoo2://zoo1.internal:2181,zoo2.internal:2181,zoo3.internal:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;transportMode=http;httpPath=cliservice;principal=hive/_HOST@TESTAD.LOCAL].

                                2020-10-26 11:21:37.961 <TASK_140713622742784-READER_1_1_1> SEVERE: [RR_4036] Error connecting to database [

                                Function [INFASQLConnectW] failed in adapter [/appl/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

                                 

                                Database driver error...

                                Function Name : Connect

                                Database driver error...

                                Function Name : Connect

                                Database Error: Failed to connect to database using user [] and connection string [jdbc:zoo2://zoo1.internal:2181,zoo2.internal:2181,zoo3.internal:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;transportMode=http;httpPath=cliservice;principal=hive/_HOST@TESTAD.LOCAL].].

                                2020-10-26 11:21:37.964 <TASK_140713622742784-READER_1_1_1> SEVERE: [BLKR_16001] Error connecting to database...

                                2020-10-26 11:21:37.968 <TASK_140713622742784-READER_1_1_1> INFO: [ODL_26103] Closing DB connection [jdbc:zoo2://zoo1.internal:2181,zoo2.internal:2181,zoo3.internal:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;transportMode=http;httpPath=cliservice;principal=hive/_HOST@TESTAD.LOCAL].

                                2020-10-26 11:21:37.972 <TASK_140713631135488-MAPPING> INFO: [PETL_24031]

                                ***** RUN INFO FOR TGT LOAD ORDER GROUP [1], CONCURRENT SET [1] *****

                                Completed the [reader] stage of the partition point [test_infa1]. The run time is not sufficient to report any statistics.

                                 

                                2020-10-26 11:21:37.976 <TASK_140713639528192-MAPPING> INFO: [CMN_1142]

                                2020-10-26 11:21:37.980 <TASK_140713639528192-MAPPING> INFO: [TT_11027] =======================================================

                                    DETAILED TRANSFORMATION ROW STATISTICS

                                    for DSQ [test_infa1], Partition[1]

                                    ----------------------------------

                                2020-10-26 11:21:37.983 <TASK_140713639528192-MAPPING> INFO: [CMN_1142]

                                2020-10-26 11:21:37.987 <TASK_140713639528192-MAPPING> INFO: [TT_11031] Transformation [test_infa1]:

                                2020-10-26 11:21:37.991 <TASK_140713639528192-MAPPING> INFO: [TT_11035] Input  - 0 (__READER__)

                                2020-10-26 11:21:37.995 <TASK_140713639528192-MAPPING> INFO: [TT_11115] [test_infa1]: Output Group Index = [0]

                                2020-10-26 11:21:37.998 <TASK_140713639528192-MAPPING> INFO: [TT_11037]     [expr_OutputParameters_OUTPUT]: Output - 0,    Dropped - 0

                                2020-10-26 11:21:38.002 <TASK_140713639528192-MAPPING> INFO: [CMN_1142]

                                2020-10-26 11:21:38.006 <TASK_140713639528192-MAPPING> INFO: [TT_11031] Transformation [expr_OutputParameters_OUTPUT]:

                                2020-10-26 11:21:38.010 <TASK_140713639528192-MAPPING> INFO: [TT_11114] [expr_OutputParameters_OUTPUT]: Input Group Index = [0], Input Row Count [0]

                                2020-10-26 11:21:38.013 <TASK_140713639528192-MAPPING> INFO: [TT_11034]     [test_infa1]: Input - 0

                                2020-10-26 11:21:38.017 <TASK_140713639528192-MAPPING> INFO: [TT_11115] [expr_OutputParameters_OUTPUT]: Output Group Index = [0]

                                2020-10-26 11:21:38.021 <TASK_140713639528192-MAPPING> INFO: [TT_11037]     [Data_Exchange_Target-expr_OutputParameters_OUTPUT]: Output - 0,    Dropped - 0

                                2020-10-26 11:21:38.025 <TASK_140713639528192-MAPPING> INFO: [CMN_1142]

                                2020-10-26 11:21:38.029 <TASK_140713639528192-MAPPING> INFO: [TT_11033] Transformation to target [Data_Exchange_Target-expr_OutputParameters_OUTPUT]:

                                2020-10-26 11:21:38.033 <TASK_140713639528192-MAPPING> INFO: [TT_11114] [Data_Exchange_Target-expr_OutputParameters_OUTPUT]: Input Group Index = [0], Input Row Count [0]

                                2020-10-26 11:21:38.038 <TASK_140713639528192-MAPPING> INFO: [TT_11034]     [expr_OutputParameters_OUTPUT]: Input - 0

                                2020-10-26 11:21:38.042 <TASK_140713639528192-MAPPING> INFO: [TT_11038] Output - 0,    Dropped - 0

                                2020-10-26 11:21:38.046 <TASK_140713639528192-MAPPING> INFO: [CMN_1142]

                                2020-10-26 11:21:38.050 <TASK_140713639528192-MAPPING> INFO: [TT_11040] =======================================================

                                 

                                2020-10-26 11:21:38.054 <TASK_140713639528192-MAPPING> INFO: [TM_6362] Pushdown cleanup SQL for source, if any, is executed.

                                2020-10-26 11:21:38.058 <TASK_140713639528192-MAPPING> INFO: [TM_6370] Pushdown cleanup SQL for target, if any, is executed.

                                2020-10-26 11:21:38.062 <TASK_140713639528192-POST-SESS> INFO: [PETL_24005] Starting post-session tasks.

                                2020-10-26 11:21:38.066 <TASK_140713639528192-POST-SESS> INFO: [PETL_24028] Post-session task completed with failure.

                                2020-10-26 11:21:38.069 <TASK_140713639528192-MAPPING> INFO: [SDKS_38510] SDK target and group deinitialized with status [-1].

                                2020-10-26 11:21:38.073 <TASK_140713639528192-MAPPING> INFO: [SDKS_38023] Plug-in 10000000's [deinit] method invocation successful.

                                2020-10-26 11:21:38.076 <TASK_140713639528192-MAPPING> INFO: [SDKS_38025] Plug-in 10000000 deinitialized and unloaded with status [-1].

                                2020-10-26 11:21:38.080 <TASK_140713639528192-MAPPING> INFO: [SDKS_38019] Writer SDK plug-ins deinitialized with status [-1].

                                2020-10-26 11:21:38.083 <TASK_140713639528192-MAPPING> INFO: [TM_6018] The session completed with [0] row transformation errors.

                                2020-10-26 11:21:38.088 <TASK_140713639528192-MAPPING> INFO: [PETL_24002] Parallel Pipeline Engine finished.

                                2020-10-26 11:21:38.092 <APP_140714135308032> INFO: [PETL_24013] Session run completed with failure.

                                2020-10-26 11:21:38.095 <APP_140714135308032> INFO: [TM_6847] Post-session variable assignment executed.

                                2020-10-26 11:21:38.099 <APP_140714135308032> INFO: [TM_6022]

                                 

                                SESSION LOAD SUMMARY

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

                                 

                                2020-10-26 11:21:38.103 <APP_140714135308032> INFO: [TM_6252] Source Load Summary.

                                2020-10-26 11:21:38.107 <APP_140714135308032> INFO: [CMN_1740] Table: [test_infa1] (Instance Name: [test_infa1])

                                     Output Rows [0], Affected Rows [0], Applied Rows [0], Rejected Rows [0]

                                2020-10-26 11:21:38.111 <APP_140714135308032> INFO: [TM_6253] Target Load Summary.

                                2020-10-26 11:21:38.114 <APP_140714135308032> INFO: [CMN_1740] Table: [Data_Exchange_Target-expr_OutputParameters_OUTPUT] (Instance Name: [Data_Exchange_Target-expr_OutputParameters_OUTPUT])

                                     Output Rows [0], Affected Rows [0], Applied Rows [0], Rejected Rows [0]

                                2020-10-26 11:21:38.118 <APP_140714135308032> INFO: [TM_6023]

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

                                 

                                2020-10-26 11:21:38.122 <APP_140714135308032> INFO: [TM_6020] Session [test_infa1] completed at [Mon Oct 26 11:21:37 2020].

                                2020-10-26 11:21:38.126 <OnDemandDTM-pool-2-thread-18> WARNING: [EdtmExec_00007] RR_4036 Error connecting to database [

                                Function [INFASQLConnectW] failed in adapter [/appl/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

                                 

                                Database driver error...

                                Function Name : Connect

                                Database driver error...

                                Function Name : Connect

                                Database Error: Failed to connect to database using user [] and connection string [jdbc:zoo2://zoo1.internal:2181,zoo2.internal:2181,zoo3.internal:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;transportMode=http;httpPath=cliservice;principal=hive/_HOST@TESTAD.LOCAL].].

                                2020-10-26 11:21:38.130 <OnDemandDTM-pool-2-thread-18> FINE: com.informatica.sdk.dtm.ExecutionException: [EdtmExec_00007] RR_4036 Error connecting to database [

                                Function [INFASQLConnectW] failed in adapter [/appl/opt/infa/plugins/dynamic/hiveruntime/libhive.so] with error code [-1].

                                 

                                Database driver error...

                                Function Name : Connect

                                Database driver error...

                                Function Name : Connect

                                Database Error: Failed to connect to database using user [] and connection string [jdbc:zoo2://zoo1.internal:2181,zoo2.internal:2181,zoo3.internal:2181/default;serviceDiscoveryMode=zooKeeper;zooKeeperNamespace=hiveserver2;transportMode=http;httpPath=cliservice;principal=hive/_HOST@TESTAD.LOCAL].].

                                    at com.informatica.dtm.executor.edtm.EdtmExecutor.createAndExeJdtm(EdtmExecutor.java:492)

                                    at com.informatica.dtm.executor.edtm.EdtmExecutor.run(EdtmExecutor.java:293)

                                    at com.informatica.platform.ldtm.executor.ExecutionEngine$SubmittedRunnable.run(ExecutionEngine.java:593)

                                    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)

                                    at java.util.concurrent.FutureTask.run(FutureTask.java:266)

                                    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)

                                    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)

                                    at java.lang.Thread.run(Thread.java:748)

                                 

                                2020-10-26 11:21:38.136 <OnDemandDTM-pool-2-thread-18> INFO: [EdtmExec_00008] Total time to perform the LDTM operation: 4,627 ms

                                • 13. Re: DEI writing to Hive with Kerberos
                                  Andrea Gruev Active Member

                                  HIVE LOG Server1

                                  ==> hivemetastore.log <==

                                  2020-10-26T11:21:17,633 INFO  [PartitionDiscoveryTask-2]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive1.bigdata.it.internal@TESTAD.LOCAL       ip=unknown-ip-addr      cmd=Cleaning up thread local RawStore...

                                  2020-10-26T11:21:17,634 INFO  [PartitionDiscoveryTask-2]: metastore.ObjectStore (ObjectStore.java:shutdown(710)) - RawStore: org.apache.hadoop.hive.metastore.ObjectStore@7222973b, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@25e45cfd will be shutdown

                                  2020-10-26T11:21:17,634 INFO  [PartitionDiscoveryTask-2]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 2654: Done cleaning up thread local RawStore

                                  2020-10-26T11:21:17,634 INFO  [PartitionDiscoveryTask-2]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive1.bigdata.it.internal@TESTAD.LOCAL       ip=unknown-ip-addr      cmd=Done cleaning up thread local RawStore

                                  2020-10-26T11:21:17,634 INFO  [pool-4-thread-3]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 167: Cleaning up thread local RawStore...

                                  2020-10-26T11:21:17,634 INFO  [pool-4-thread-3]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive1.bigdata.it.internal@TESTAD.LOCALip=unknown-ip-addr      cmd=Cleaning up thread local RawStore...

                                  2020-10-26T11:21:17,634 INFO  [pool-4-thread-3]: metastore.ObjectStore (ObjectStore.java:shutdown(710)) - RawStore: org.apache.hadoop.hive.metastore.ObjectStore@36c94290, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@34fd7627 will be shutdown

                                  2020-10-26T11:21:17,634 INFO  [pool-4-thread-3]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 167: Done cleaning up thread local RawStore

                                  2020-10-26T11:21:17,634 INFO  [pool-4-thread-3]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive1.bigdata.it.internal@TESTAD.LOCALip=unknown-ip-addr      cmd=Done cleaning up thread local RawStore

                                  2020-10-26T11:21:22,104 INFO  [pool-4-thread-4]: txn.AcidOpenTxnsCounterService (AcidOpenTxnsCounterService.java:run(51)) - AcidOpenTxnsCounterService ran for 0 seconds.  isAliveCounter = 250218

                                   

                                  ==> hiveserver2.log <==

                                  2020-10-26T11:20:41,006 INFO  [40f4a179-8009-4152-8724-0e0d7654d4bf HiveServer2-HttpHandler-Pool: Thread-18288]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 40f4a179-8009-4152-8724-0e0d7654d4bf

                                  2020-10-26T11:20:41,011 INFO  [HiveServer2-HttpHandler-Pool: Thread-18042]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 40f4a179-8009-4152-8724-0e0d7654d4bf

                                  2020-10-26T11:20:41,011 INFO  [40f4a179-8009-4152-8724-0e0d7654d4bf HiveServer2-HttpHandler-Pool: Thread-18042]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 40f4a179-8009-4152-8724-0e0d7654d4bf

                                  2020-10-26T11:20:41,036 INFO  [HiveServer2-HttpHandler-Pool: Thread-18288]: service.CompositeService (:()) - Session closed, SessionHandle [40f4a179-8009-4152-8724-0e0d7654d4bf], current sessions:0

                                  2020-10-26T11:20:41,036 INFO  [HiveServer2-HttpHandler-Pool: Thread-18288]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 40f4a179-8009-4152-8724-0e0d7654d4bf

                                  2020-10-26T11:20:41,036 INFO  [40f4a179-8009-4152-8724-0e0d7654d4bf HiveServer2-HttpHandler-Pool: Thread-18288]: session.HiveSessionImpl (:()) - Operation log session directory is deleted: /tmp/hive/operation_logs/40f4a179-8009-4152-8724-0e0d7654d4bf

                                  2020-10-26T11:20:41,036 INFO  [40f4a179-8009-4152-8724-0e0d7654d4bf HiveServer2-HttpHandler-Pool: Thread-18288]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 40f4a179-8009-4152-8724-0e0d7654d4bf

                                  2020-10-26T11:20:41,043 INFO  [HiveServer2-HttpHandler-Pool: Thread-18288]: session.SessionState (:()) - Deleted directory: /tmp/hive/hive/40f4a179-8009-4152-8724-0e0d7654d4bf on fs with scheme hdfs

                                  2020-10-26T11:20:41,043 INFO  [HiveServer2-HttpHandler-Pool: Thread-18288]: session.SessionState (:()) - Deleted directory: /tmp/hive/40f4a179-8009-4152-8724-0e0d7654d4bf on fs with scheme file

                                  2020-10-26T11:20:41,043 INFO  [HiveServer2-HttpHandler-Pool: Thread-18288]: metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore, current connections: 4

                                  2020-10-26T11:21:40,738 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: thrift.ThriftHttpServlet (:()) - Could not validate cookie sent, will try to generate a new cookie

                                  2020-10-26T11:21:40,739 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: thrift.ThriftHttpServlet (:()) - Failed to authenticate with http/_HOST kerberos principal, trying with hive/_HOST kerberos principal

                                  2020-10-26T11:21:40,739 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: thrift.ThriftHttpServlet (:()) - Cookie added for clientUserName ambari-qa

                                  2020-10-26T11:21:40,739 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: thrift.ThriftCLIService (:()) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V10

                                  2020-10-26T11:21:40,769 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: session.SessionState (:()) - Created HDFS directory: /tmp/hive/hive/8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:40,774 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: session.SessionState (:()) - Created local directory: /tmp/hive/8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:40,795 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: session.SessionState (:()) - Created HDFS directory: /tmp/hive/hive/8030f4c4-bea2-4a31-a9b0-49586a2dfd95/_tmp_space.db

                                  2020-10-26T11:21:40,796 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI thrift://hive2.bigdata.it.internal:9083

                                  2020-10-26T11:21:40,796 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: metastore.HiveMetaStoreClient (:()) - HMSC::open(): Could not find delegation token. Creating KERBEROS-based thrift connection.

                                  2020-10-26T11:21:40,798 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore, current connections: 5

                                  2020-10-26T11:21:40,798 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: metastore.HiveMetaStoreClient (:()) - Connected to metastore.

                                  2020-10-26T11:21:40,798 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive/hive1.bigdata.it.internal@TESTAD.LOCAL (auth:KERBEROS) retries=24 delay=5 lifetime=0

                                   

                                  ==> hivemetastore.log <==

                                  2020-10-26T11:21:40,861 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 245: get_database: default

                                  2020-10-26T11:21:40,861 INFO  [pool-8-thread-198]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive2.bigdata.it.internal@TESTAD.LOCAL      ip=192.168.1.149       cmd=get_database: default

                                  2020-10-26T11:21:40,862 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:newRawStoreForConf(774)) - 245: Opening raw store with implementation class:org.apache.hadoop.hive.metastore.ObjectStore

                                   

                                  ==> hiveserver2.log <==

                                  2020-10-26T11:21:40,958 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: session.HiveSessionImpl (:()) - Operation log session directory is created: /tmp/hive/operation_logs/8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:40,958 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: service.CompositeService (:()) - Session opened, SessionHandle [8030f4c4-bea2-4a31-a9b0-49586a2dfd95], current sessions:1

                                   

                                  ==> hivemetastore.log <==

                                  2020-10-26T11:21:40,970 INFO  [pool-8-thread-198]: metastore.ObjectStore (ObjectStore.java:shutdown(710)) - RawStore: org.apache.hadoop.hive.metastore.ObjectStore@21e1a09b, with PersistenceManager: null will be shutdown

                                  2020-10-26T11:21:40,970 INFO  [pool-8-thread-198]: metastore.ObjectStore (ObjectStore.java:initializeHelper(493)) - ObjectStore, initialize called

                                  2020-10-26T11:21:40,970 INFO  [pool-8-thread-198]: metastore.ObjectStore (ObjectStore.java:initializeHelper(496)) - RawStore: org.apache.hadoop.hive.metastore.ObjectStore@21e1a09b, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@749ed496 created in the thread with id: 3642

                                  2020-10-26T11:21:40,994 INFO  [pool-8-thread-198]: metastore.MetaStoreDirectSql (MetaStoreDirectSql.java:<init>(189)) - Using direct SQL, underlying DB is MYSQL

                                  2020-10-26T11:21:40,994 INFO  [pool-8-thread-198]: metastore.ObjectStore (ObjectStore.java:setConf(407)) - Initialized ObjectStore

                                  2020-10-26T11:21:40,994 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:getMSForConf(752)) - Created RawStore: org.apache.hadoop.hive.metastore.ObjectStore@21e1a09b from thread id: 3642

                                  2020-10-26T11:21:41,001 INFO  [pool-8-thread-198]: authorization.StorageBasedAuthorizationProvider (StorageBasedAuthorizationProvider.java:userHasProxyPrivilege(172)) - user hive has host proxy privilege.

                                  2020-10-26T11:21:41,002 INFO  [pool-8-thread-198]: authorization.StorageBasedAuthorizationProvider (StorageBasedAuthorizationProvider.java:checkPermissions(395)) - Path authorization is skipped for path hdfs://hdpp02/warehouse/tablespace/external/hive.

                                  2020-10-26T11:21:41,002 INFO  [pool-8-thread-198]: metastore.MetastoreDefaultTransformer (MetastoreDefaultTransformer.java:transformDatabase(627)) - Starting translation for transformDatabase for processor HMSClient-@hive2.bigdata.it.internal with [EXTWRITE, EXTREAD, HIVEBUCKET2, HIVEFULLACIDREAD, HIVEFULLACIDWRITE, HIVECACHEINVALIDATE, HIVEMANAGESTATS, HIVEMANAGEDINSERTWRITE, HIVEMANAGEDINSERTREAD, HIVESQL, HIVEMQT, HIVEONLYMQTWRITE] on database default

                                  2020-10-26T11:21:41,002 INFO  [pool-8-thread-198]: metastore.MetastoreDefaultTransformer (MetastoreDefaultTransformer.java:transformDatabase(638)) - Transformer returning database:Database(name:default, description:Default Hive database, locationUri:hdfs://hdpp02/warehouse/tablespace/managed/hive, parameters:{}, ownerName:public, ownerType:ROLE, catalogName:hive)

                                   

                                  ==> hiveserver2.log <==

                                  2020-10-26T11:21:41,041 INFO  [HiveServer2-HttpHandler-Pool: Thread-18249]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:41,041 INFO  [8030f4c4-bea2-4a31-a9b0-49586a2dfd95 HiveServer2-HttpHandler-Pool: Thread-18249]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:41,049 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:41,050 INFO  [8030f4c4-bea2-4a31-a9b0-49586a2dfd95 HiveServer2-HttpHandler-Pool: Thread-18240]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:41,058 INFO  [HiveServer2-HttpHandler-Pool: Thread-18249]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:41,058 INFO  [8030f4c4-bea2-4a31-a9b0-49586a2dfd95 HiveServer2-HttpHandler-Pool: Thread-18249]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:41,085 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: service.CompositeService (:()) - Session closed, SessionHandle [8030f4c4-bea2-4a31-a9b0-49586a2dfd95], current sessions:0

                                  2020-10-26T11:21:41,085 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:41,086 INFO  [8030f4c4-bea2-4a31-a9b0-49586a2dfd95 HiveServer2-HttpHandler-Pool: Thread-18240]: session.HiveSessionImpl (:()) - Operation log session directory is deleted: /tmp/hive/operation_logs/8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:41,086 INFO  [8030f4c4-bea2-4a31-a9b0-49586a2dfd95 HiveServer2-HttpHandler-Pool: Thread-18240]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 8030f4c4-bea2-4a31-a9b0-49586a2dfd95

                                  2020-10-26T11:21:41,109 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: session.SessionState (:()) - Deleted directory: /tmp/hive/hive/8030f4c4-bea2-4a31-a9b0-49586a2dfd95 on fs with scheme hdfs

                                  2020-10-26T11:21:41,109 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: session.SessionState (:()) - Deleted directory: /tmp/hive/8030f4c4-bea2-4a31-a9b0-49586a2dfd95 on fs with scheme file

                                  2020-10-26T11:21:41,109 INFO  [HiveServer2-HttpHandler-Pool: Thread-18240]: metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore, current connections: 4

                                   

                                  ==> hivemetastore.log <==

                                  2020-10-26T11:21:41,139 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 245: Cleaning up thread local RawStore...

                                  2020-10-26T11:21:41,139 INFO  [pool-8-thread-198]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive2.bigdata.it.internal@TESTAD.LOCAL      ip=192.168.1.149       cmd=Cleaning up thread local RawStore...

                                  2020-10-26T11:21:41,139 INFO  [pool-8-thread-198]: metastore.ObjectStore (ObjectStore.java:shutdown(710)) - RawStore: org.apache.hadoop.hive.metastore.ObjectStore@21e1a09b, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@749ed496 will be shutdown

                                  2020-10-26T11:21:41,139 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 245: Done cleaning up thread local RawStore

                                  2020-10-26T11:21:41,140 INFO  [pool-8-thread-198]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive2.bigdata.it.internal@TESTAD.LOCAL      ip=192.168.1.149       cmd=Done cleaning up thread local RawStore

                                  2020-10-26T11:21:41,140 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 245: Done cleaning up thread local RawStore

                                  2020-10-26T11:21:41,140 INFO  [pool-8-thread-198]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive1.bigdata.it.internal@TESTAD.LOCAL      ip=192.168.1.149       cmd=Done cleaning up thread local RawStore

                                  • 14. Re: DEI writing to Hive with Kerberos
                                    Andrea Gruev Active Member

                                    Hive Log Server2:

                                    ==> hivemetastore.log <==

                                    Caused by: org.apache.thrift.transport.TSaslTransportException: No data or no sasl data in the stream

                                            at org.apache.thrift.transport.TSaslTransport.open(TSaslTransport.java:326) ~[hive-exec-3.1.0.3.1.5.0-152.jar:3.1.0.3.1.5.0-152]

                                            at org.apache.thrift.transport.TSaslServerTransport.open(TSaslServerTransport.java:41) ~[hive-exec-3.1.0.3.1.5.0-152.jar:3.1.0.3.1.5.0-152]

                                            at org.apache.thrift.transport.TSaslServerTransport$Factory.getTransport(TSaslServerTransport.java:216) ~[hive-exec-3.1.0.3.1.5.0-152.jar:3.1.0.3.1.5.0-152]

                                            ... 10 more

                                    2020-10-26T11:20:40,703 INFO  [pool-8-thread-1]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 1: get_database: default

                                    2020-10-26T11:20:40,703 INFO  [pool-8-thread-1]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=spark/hive2.bigdata.it.internal@TESTAD.LOCAL       ip=192.168.1.132       cmd=get_database: default

                                    2020-10-26T11:20:40,735 INFO  [pool-8-thread-1]: metastore.MetastoreDefaultTransformer (MetastoreDefaultTransformer.java:transformDatabase(627)) - Starting translation for transformDatabase for processor Spark with [SPARKSQL, EXTREAD, EXTWRITE, HIVESQL] on database default

                                    2020-10-26T11:20:40,735 INFO  [pool-8-thread-1]: metastore.MetastoreDefaultTransformer (MetastoreDefaultTransformer.java:transformDatabase(632)) - Processor does not have any of ACID write capabilities, changing current location from hdfs://hdpp02/warehouse/tablespace/managed/hive to external warehouse location

                                    2020-10-26T11:20:40,735 INFO  [pool-8-thread-1]: metastore.MetastoreDefaultTransformer (MetastoreDefaultTransformer.java:transformDatabase(638)) - Transformer returning database:Database(name:default, description:Default Hive database, locationUri:hdfs://hdpp02/warehouse/tablespace/external/hive, parameters:{}, ownerName:public, ownerType:ROLE, catalogName:hive)

                                     

                                    ==> hiveserver2.log <==

                                    2020-10-26T11:20:41,211 INFO  [4ba1f36f-0178-41b6-a22e-462f2733e5e6 HiveServer2-HttpHandler-Pool: Thread-18295]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4ba1f36f-0178-41b6-a22e-462f2733e5e6

                                    2020-10-26T11:20:41,217 INFO  [HiveServer2-HttpHandler-Pool: Thread-18274]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4ba1f36f-0178-41b6-a22e-462f2733e5e6

                                    2020-10-26T11:20:41,217 INFO  [4ba1f36f-0178-41b6-a22e-462f2733e5e6 HiveServer2-HttpHandler-Pool: Thread-18274]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4ba1f36f-0178-41b6-a22e-462f2733e5e6

                                    2020-10-26T11:20:41,241 INFO  [HiveServer2-HttpHandler-Pool: Thread-18295]: service.CompositeService (:()) - Session closed, SessionHandle [4ba1f36f-0178-41b6-a22e-462f2733e5e6], current sessions:1

                                    2020-10-26T11:20:41,241 INFO  [HiveServer2-HttpHandler-Pool: Thread-18295]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4ba1f36f-0178-41b6-a22e-462f2733e5e6

                                    2020-10-26T11:20:41,242 INFO  [4ba1f36f-0178-41b6-a22e-462f2733e5e6 HiveServer2-HttpHandler-Pool: Thread-18295]: session.HiveSessionImpl (:()) - Operation log session directory is deleted: /tmp/hive/operation_logs/4ba1f36f-0178-41b6-a22e-462f2733e5e6

                                    2020-10-26T11:20:41,242 INFO  [4ba1f36f-0178-41b6-a22e-462f2733e5e6 HiveServer2-HttpHandler-Pool: Thread-18295]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 4ba1f36f-0178-41b6-a22e-462f2733e5e6

                                    2020-10-26T11:20:41,259 INFO  [HiveServer2-HttpHandler-Pool: Thread-18295]: session.SessionState (:()) - Deleted directory: /tmp/hive/hive/4ba1f36f-0178-41b6-a22e-462f2733e5e6 on fs with scheme hdfs

                                    2020-10-26T11:20:41,259 INFO  [HiveServer2-HttpHandler-Pool: Thread-18295]: session.SessionState (:()) - Deleted directory: /tmp/hive/4ba1f36f-0178-41b6-a22e-462f2733e5e6 on fs with scheme file

                                    2020-10-26T11:20:41,259 INFO  [HiveServer2-HttpHandler-Pool: Thread-18295]: metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore, current connections: 4

                                     

                                    ==> hivemetastore.log <==

                                    2020-10-26T11:21:39,083 INFO  [pool-8-thread-1]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 1: get_database: default

                                    2020-10-26T11:21:39,084 INFO  [pool-8-thread-1]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=spark/hive2.bigdata.it.internal@TESTAD.LOCAL       ip=192.168.1.132       cmd=get_database: default

                                    2020-10-26T11:21:39,116 INFO  [pool-8-thread-1]: metastore.MetastoreDefaultTransformer (MetastoreDefaultTransformer.java:transformDatabase(627)) - Starting translation for transformDatabase for processor Spark with [SPARKSQL, EXTREAD, EXTWRITE, HIVESQL] on database default

                                    2020-10-26T11:21:39,116 INFO  [pool-8-thread-1]: metastore.MetastoreDefaultTransformer (MetastoreDefaultTransformer.java:transformDatabase(632)) - Processor does not have any of ACID write capabilities, changing current location from hdfs://hdpp02/warehouse/tablespace/managed/hive to external warehouse location

                                    2020-10-26T11:21:39,116 INFO  [pool-8-thread-1]: metastore.MetastoreDefaultTransformer (MetastoreDefaultTransformer.java:transformDatabase(638)) - Transformer returning database:Database(name:default, description:Default Hive database, locationUri:hdfs://hdpp02/warehouse/tablespace/external/hive, parameters:{}, ownerName:public, ownerType:ROLE, catalogName:hive)

                                    2020-10-26T11:21:40,798 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 154: get_database: default

                                    2020-10-26T11:21:40,798 INFO  [pool-8-thread-198]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive1.bigdata.it.internal@TESTAD.LOCAL      ip=192.168.1.148       cmd=get_database: default

                                    2020-10-26T11:21:40,799 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:newRawStoreForConf(774)) - 154: Opening raw store with implementation class:org.apache.hadoop.hive.metastore.ObjectStore

                                     

                                    ==> hiveserver2.log <==

                                    2020-10-26T11:21:40,815 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: thrift.ThriftHttpServlet (:()) - Could not validate cookie sent, will try to generate a new cookie

                                    2020-10-26T11:21:40,816 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: thrift.ThriftHttpServlet (:()) - Failed to authenticate with http/_HOST kerberos principal, trying with hive/_HOST kerberos principal

                                    2020-10-26T11:21:40,816 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: thrift.ThriftHttpServlet (:()) - Cookie added for clientUserName ambari-qa

                                    2020-10-26T11:21:40,816 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: thrift.ThriftCLIService (:()) - Client protocol version: HIVE_CLI_SERVICE_PROTOCOL_V10

                                    2020-10-26T11:21:40,834 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: session.SessionState (:()) - Created HDFS directory: /tmp/hive/hive/41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:40,837 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: session.SessionState (:()) - Created local directory: /tmp/hive/41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:40,857 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: session.SessionState (:()) - Created HDFS directory: /tmp/hive/hive/41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c/_tmp_space.db

                                    2020-10-26T11:21:40,858 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: metastore.HiveMetaStoreClient (:()) - Trying to connect to metastore with URI thrift://hive1.bigdata.it.internal:9083

                                    2020-10-26T11:21:40,858 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: metastore.HiveMetaStoreClient (:()) - HMSC::open(): Could not find delegation token. Creating KERBEROS-based thrift connection.

                                    2020-10-26T11:21:40,861 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: metastore.HiveMetaStoreClient (:()) - Opened a connection to metastore, current connections: 5

                                    2020-10-26T11:21:40,861 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: metastore.HiveMetaStoreClient (:()) - Connected to metastore.

                                    2020-10-26T11:21:40,861 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: metastore.RetryingMetaStoreClient (:()) - RetryingMetaStoreClient proxy=class org.apache.hadoop.hive.ql.metadata.SessionHiveMetaStoreClient ugi=hive/av3l371d.bigdata.it.internal@TESTAD.LOCAL (auth:KERBEROS) retries=24 delay=5 lifetime=0

                                     

                                    ==> hivemetastore.log <==

                                    2020-10-26T11:21:40,907 INFO  [pool-8-thread-198]: metastore.ObjectStore (ObjectStore.java:shutdown(710)) - RawStore: org.apache.hadoop.hive.metastore.ObjectStore@3ae9419e, with PersistenceManager: null will be shutdown

                                    2020-10-26T11:21:40,907 INFO  [pool-8-thread-198]: metastore.ObjectStore (ObjectStore.java:initializeHelper(493)) - ObjectStore, initialize called

                                    2020-10-26T11:21:40,908 INFO  [pool-8-thread-198]: metastore.ObjectStore (ObjectStore.java:initializeHelper(496)) - RawStore: org.apache.hadoop.hive.metastore.ObjectStore@3ae9419e, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@2e9d9f76 created in the thread with id: 1015

                                    2020-10-26T11:21:40,948 INFO  [pool-8-thread-198]: metastore.MetaStoreDirectSql (MetaStoreDirectSql.java:<init>(189)) - Using direct SQL, underlying DB is MYSQL

                                    2020-10-26T11:21:40,948 INFO  [pool-8-thread-198]: metastore.ObjectStore (ObjectStore.java:setConf(407)) - Initialized ObjectStore

                                    2020-10-26T11:21:40,948 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:getMSForConf(752)) - Created RawStore: org.apache.hadoop.hive.metastore.ObjectStore@3ae9419e from thread id: 1015

                                    2020-10-26T11:21:40,958 INFO  [pool-8-thread-198]: authorization.StorageBasedAuthorizationProvider (StorageBasedAuthorizationProvider.java:userHasProxyPrivilege(172)) - user hive has host proxy privilege.

                                    2020-10-26T11:21:40,958 INFO  [pool-8-thread-198]: authorization.StorageBasedAuthorizationProvider (StorageBasedAuthorizationProvider.java:checkPermissions(395)) - Path authorization is skipped for path hdfs://hdpp02/warehouse/tablespace/external/hive.

                                    2020-10-26T11:21:40,958 INFO  [pool-8-thread-198]: metastore.MetastoreDefaultTransformer (MetastoreDefaultTransformer.java:transformDatabase(627)) - Starting translation for transformDatabase for processor HMSClient-@hive1.bigdata.it.internal with [EXTWRITE, EXTREAD, HIVEBUCKET2, HIVEFULLACIDREAD, HIVEFULLACIDWRITE, HIVECACHEINVALIDATE, HIVEMANAGESTATS, HIVEMANAGEDINSERTWRITE, HIVEMANAGEDINSERTREAD, HIVESQL, HIVEMQT, HIVEONLYMQTWRITE] on database default

                                    2020-10-26T11:21:40,958 INFO  [pool-8-thread-198]: metastore.MetastoreDefaultTransformer (MetastoreDefaultTransformer.java:transformDatabase(638)) - Transformer returning database:Database(name:default, description:Default Hive database, locationUri:hdfs://hdpp02/warehouse/tablespace/managed/hive, parameters:{}, ownerName:public, ownerType:ROLE, catalogName:hive)

                                     

                                    ==> hiveserver2.log <==

                                    2020-10-26T11:21:41,002 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: session.HiveSessionImpl (:()) - Operation log session directory is created: /tmp/hive/operation_logs/41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:41,002 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: service.CompositeService (:()) - Session opened, SessionHandle [41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c], current sessions:2

                                    2020-10-26T11:21:41,084 INFO  [HiveServer2-HttpHandler-Pool: Thread-17893]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:41,084 INFO  [41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c HiveServer2-HttpHandler-Pool: Thread-17893]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:41,093 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:41,093 INFO  [41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c HiveServer2-HttpHandler-Pool: Thread-18145]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:41,099 INFO  [HiveServer2-HttpHandler-Pool: Thread-17893]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:41,100 INFO  [41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c HiveServer2-HttpHandler-Pool: Thread-17893]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                     

                                    ==> hivemetastore.log <==

                                    2020-10-26T11:21:41,109 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 154: Cleaning up thread local RawStore...

                                    2020-10-26T11:21:41,109 INFO  [pool-8-thread-198]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive1.bigdata.it.internal@TESTAD.LOCAL      ip=192.168.1.148       cmd=Cleaning up thread local RawStore...

                                    2020-10-26T11:21:41,109 INFO  [pool-8-thread-198]: metastore.ObjectStore (ObjectStore.java:shutdown(710)) - RawStore: org.apache.hadoop.hive.metastore.ObjectStore@3ae9419e, with PersistenceManager: org.datanucleus.api.jdo.JDOPersistenceManager@2e9d9f76 will be shutdown

                                    2020-10-26T11:21:41,110 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 154: Done cleaning up thread local RawStore

                                    2020-10-26T11:21:41,110 INFO  [pool-8-thread-198]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive1.bigdata.it.internal@TESTAD.LOCAL      ip=192.168.1.148       cmd=Done cleaning up thread local RawStore

                                    2020-10-26T11:21:41,110 INFO  [pool-8-thread-198]: metastore.HiveMetaStore (HiveMetaStore.java:logInfo(952)) - 154: Done cleaning up thread local RawStore

                                    2020-10-26T11:21:41,110 INFO  [pool-8-thread-198]: HiveMetaStore.audit (HiveMetaStore.java:logAuditEvent(360)) - ugi=hive/hive1.bigdata.it.internal@TESTAD.LOCAL      ip=192.168.1.148       cmd=Done cleaning up thread local RawStore

                                     

                                    ==> hiveserver2.log <==

                                    2020-10-26T11:21:41,125 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: service.CompositeService (:()) - Session closed, SessionHandle [41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c], current sessions:1

                                    2020-10-26T11:21:41,125 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:41,126 INFO  [41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c HiveServer2-HttpHandler-Pool: Thread-18145]: session.HiveSessionImpl (:()) - Operation log session directory is deleted: /tmp/hive/operation_logs/41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:41,126 INFO  [41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c HiveServer2-HttpHandler-Pool: Thread-18145]: conf.HiveConf (HiveConf.java:getLogIdVar(5264)) - Using the default value passed in for log id: 41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c

                                    2020-10-26T11:21:41,139 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: session.SessionState (:()) - Deleted directory: /tmp/hive/hive/41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c on fs with scheme hdfs

                                    2020-10-26T11:21:41,139 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: session.SessionState (:()) - Deleted directory: /tmp/hive/41b2e10c-7a3a-4c5a-8cd3-737e7aaad20c on fs with scheme file

                                    2020-10-26T11:21:41,139 INFO  [HiveServer2-HttpHandler-Pool: Thread-18145]: metastore.HiveMetaStoreClient (:()) - Closed a connection to metastore, current connections: 4

                                    1 2 Previous Next