Job stucked after Initialize Feed

[zhijia lin]

I have uploaded the standard data ingestion template to kylo and added a job ingested data from a mysql table which only has 1 record with around 10 cloumns, after enabling , it keeps in the "started" status for 1+ hours.

By checking  the nifi, seems it stucks in in "Initializ Feed?" which seems is doing some rest stuff

Pleaes find the application.properties in the attachenment.  and there is an info in the kylo-services.log

kylo-services.log:2017-05-15 16:18:57 INFO  main:JerseyRestClient:205 - Created new Jersey Client without SSL connecting to http://NOT_SET 

kylo-services.log.2017-05-14:2017-05-14 23:43:43 INFO  main:JerseyRestClient:205 - Created new Jersey Client without SSL connecting to http://NOT_SET 

Any ideas?  Thanks a ton!

[zhijia lin]

When stucking in above step 9, the kylo-service.log is:

2017-05-15 19:00:31 INFO  http-nio-8420-exec-3:KerberosUtil:42 - Initializing Kerberos ticket for Hive connection

2017-05-15 19:00:31 INFO  http-nio-8420-exec-3:KerberosUtil:42 - Initializing Kerberos ticket for Hive connection

2017-05-15 19:00:34 INFO  http-nio-8420-exec-7:NifiIntegrationRestController:345 - Describe Table VERSION against service: mysql-edgenode(0a19dc48-015c-1000-abbf-a157e7f00f5c)

2017-05-15 19:00:34 INFO  http-nio-8420-exec-7:DBCPConnectionPoolTableInfo:207 - describing Table hive.VERSION against Controller Service: mysql-edgenode (0a19dc48-015c-1000-abbf-a157e7f00f5c) with uri of jdbc:mysql://host1 

2017-05-15 19:00:34 INFO  http-nio-8420-exec-7:KerberosUtil:42 - Initializing Kerberos ticket for Hive connection

2017-05-15 19:00:34 INFO  http-nio-8420-exec-7:KerberosUtil:42 - Initializing Kerberos ticket for Hive connection

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:CreateFeedBuilder:302 - Aligning Feed flows in NiFi 

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:160 - Arrange Group ProcessGroupToOutputPort

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:248 - Aligned Port poc to standard-cleanup at -120.0,0.0

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:248 - Aligned Port poc to standard-ingest at -120.0,680.0

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:273 - Aligned ProcessGroup test2 at -190.0,255.0

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:273 - Aligned ProcessGroup test3 at -720.0,255.0

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:273 - Aligned ProcessGroup test1 at 340.0,255.0

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:CreateFeedBuilder:309 - This is the first feed created in the category poc.  Aligning the categories. 

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:160 - Arrange Group ProcessGroupToProcessGroup

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:273 - Aligned ProcessGroup reusable_templates at -190.0,370.0

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:273 - Aligned ProcessGroup poc at -720.0,0.0

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:160 - Arrange Group ProcessGroupWithoutConnections

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:AlignProcessGroupComponents:273 - Aligned ProcessGroup kylo_temporary_template_inspection at -190.0,1040.0

2017-05-15 19:01:39 INFO  http-nio-8420-exec-2:RegisteredTemplateService:377 - Merging properties for template Data Ingest (2ba2a11c-e739-448b-b0ce-4fca2c26ce7b)

2017-05-15 19:01:46 INFO  http-nio-8420-exec-6:RegisteredTemplateService:377 - Merging properties for template Data Ingest (2ba2a11c-e739-448b-b0ce-4fca2c26ce7b)

2017-05-15 19:01:46 INFO  http-nio-8420-exec-3:ReflectionPolicyAnnotationDiscoverer:48 - Found 2 classes annotated with interface com.thinkbiganalytics.metadata.sla.api.ServiceLevelAgreementMetric 

2017-05-15 19:01:47 INFO  DefaultMessageListenerContainer-1:ProvenanceEventReceiver:185 - About to process 13 events from the thinkbig.feed-manager queue 

2017-05-15 19:01:47 INFO  DefaultMessageListenerContainer-1:JpaBatchStepExecutionProvider:141 - New Step Execution Strip Header on Job: 15 using event 2174414 

2017-05-15 19:01:47 INFO  DefaultMessageListenerContainer-1:JpaBatchStepExecutionProvider:141 - New Step Execution Set Feed Defaults on Job: 15 using event 2174413 

2017-05-15 19:01:48 INFO  DefaultMessageListenerContainer-1:JpaBatchStepExecutionProvider:141 - New Step Execution Merge Content on Job: 15 using event 2174419 

2017-05-15 19:01:48 INFO  DefaultMessageListenerContainer-1:JpaBatchStepExecutionProvider:141 - New Step Execution Initialize Feed? on Job: 15 using event 2174422 

2017-05-15 19:01:48 INFO  DefaultMessageListenerContainer-1:JpaBatchStepExecutionProvider:141 - New Step Execution Archive Originals on Job: 15 using event 2174416 

2017-05-15 19:01:48 INFO  DefaultMessageListenerContainer-1:JpaBatchStepExecutionProvider:141 - New Step Execution UpdateTimestamp on Job: 15 using event 2174421 

2017-05-15 19:01:48 INFO  DefaultMessageListenerContainer-1:JpaBatchStepExecutionProvider:141 - New Step Execution Database on Job: 15 using event 2174410 

2017-05-15 19:01:48 INFO  DefaultMessageListenerContainer-1:JpaBatchStepExecutionProvider:141 - New Step Execution Initialize Feed Parameters on Job: 15 using event 2174412 

2017-05-15 19:01:48 INFO  DefaultMessageListenerContainer-1:JpaBatchStepExecutionProvider:141 - New Step Execution Fetch RDBMS Data on Job: 15 using event 2174411 

in nifi-app.log,  it is:

2017-05-15 19:01:42,795 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] End of hadoop configuration read

2017-05-15 19:01:42,795 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Start of HDFS timeout check

2017-05-15 19:01:42,796 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] End of HDFS timeout check

2017-05-15 19:01:42,796 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Start of Kerberos Security Check

2017-05-15 19:01:42,808 INFO [Timer-Driven Process Thread-8] o.a.hadoop.security.UserGroupInformation Login successful for user nifi/ho...@LOCAL.ALIPAY.NET using keytab file /etc/security/keytabs/nifi.headless.keytab

2017-05-15 19:01:42,808 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] End of Kerberos Security Check

2017-05-15 19:01:42,808 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /model.db/poc

2017-05-15 19:01:42,808 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /model.db/poc 

2017-05-15 19:01:42,820 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /model.db/poc/test3

2017-05-15 19:01:42,820 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /model.db/poc/test3 

2017-05-15 19:01:42,825 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Successfully created path /model.db/poc/test3

2017-05-15 19:01:42,825 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /model.db/poc/test3/feed

2017-05-15 19:01:42,825 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /model.db/poc/test3/feed 

2017-05-15 19:01:42,835 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Successfully created path /model.db/poc/test3/feed

2017-05-15 19:01:42,835 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /model.db/poc/test3/valid

2017-05-15 19:01:42,835 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /model.db/poc/test3/valid 

2017-05-15 19:01:42,842 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Successfully created path /model.db/poc/test3/valid

2017-05-15 19:01:42,842 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /model.db/poc/test3/invalid

2017-05-15 19:01:42,842 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /model.db/poc/test3/invalid 

2017-05-15 19:01:42,846 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Successfully created path /model.db/poc/test3/invalid

2017-05-15 19:01:42,846 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /model.db/poc

2017-05-15 19:01:42,846 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /model.db/poc 

2017-05-15 19:01:42,846 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /model.db/poc/test3

2017-05-15 19:01:42,846 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /model.db/poc/test3 

2017-05-15 19:01:42,847 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /model.db/poc/test3/profile

2017-05-15 19:01:42,847 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /model.db/poc/test3/profile 

2017-05-15 19:01:42,860 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Successfully created path /model.db/poc/test3/profile

2017-05-15 19:01:42,860 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /app/warehouse

2017-05-15 19:01:42,860 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /app/warehouse 

2017-05-15 19:01:42,861 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /app/warehouse/poc/

2017-05-15 19:01:42,861 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /app/warehouse/poc 

2017-05-15 19:01:42,861 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /app/warehouse/poc/test3

2017-05-15 19:01:42,861 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /app/warehouse/poc/test3 

2017-05-15 19:01:42,864 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Successfully created path /app/warehouse/poc/test3

2017-05-15 19:01:42,864 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /etl/poc

2017-05-15 19:01:42,864 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /etl/poc 

2017-05-15 19:01:42,865 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] Creating folder /etl/poc/test3

2017-05-15 19:01:42,865 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Creating path /etl/poc/test3 

2017-05-15 19:01:42,869 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.HDFSSupport Successfully created path /etl/poc/test3

2017-05-15 19:01:42,869 INFO [Timer-Driven Process Thread-8] c.t.nifi.v2.hdfs.CreateHDFSFolder CreateHDFSFolder[id=2b1f1ef0-4e0a-1bd6-7127-b415d62e1d2d] created folders /model.db/poc

/model.db/poc/test3

/model.db/poc/test3/feed

/model.db/poc/test3/valid

/model.db/poc/test3/invalid

/model.db/poc

/model.db/poc/test3

/model.db/poc/test3/profile

/app/warehouse

/app/warehouse/poc/

/app/warehouse/poc/test3

/etl/poc

/etl/poc/test3 in 93 milliseconds

2017-05-15 19:01:46,724 INFO [Provenance Maintenance Thread-2] o.a.n.p.PersistentProvenanceRepository Created new Provenance Event Writers for events starting with ID 2174423

2017-05-15 19:01:46,756 INFO [Provenance Repository Rollover Thread-2] o.a.n.p.PersistentProvenanceRepository Successfully merged 16 journal files (13 records) into single Provenance Log File /opt/nifi/data/provenance_repository/2174410.prov in 32 milliseconds

2017-05-15 19:01:46,756 INFO [Provenance Repository Rollover Thread-2] o.a.n.p.PersistentProvenanceRepository Successfully Rolled over Provenance Event file containing 11860 records

2017-05-15 19:01:47,785 INFO [Timer-Driven Process Thread-10] c.t.n.p.r.KyloProvenanceEventReportingTask KyloProvenanceEventReportingTask[id=07a2dee1-015c-1000-ab89-7a38f90158c7] KyloProvenanceEventReportingTask onTrigger Info: KyloFlowCache Sync Id: 3ecaa664-706e-43a3-9c65-1134862b7292 . Attempting to process 13 events starting with event id: 2174410.  Splitting into 1 batches of 500 each 

2017-05-15 19:01:47,815 INFO [Timer-Driven Process Thread-10] c.t.n.p.j.ProvenanceEventActiveMqWriter SENDING Events to JMS ProvenanceEventRecordDTOHolder{events=13} 

2017-05-15 19:01:47,815 INFO [Timer-Driven Process Thread-10] c.t.activemq.SendJmsMessage Sending ActiveMQ message [ProvenanceEventRecordDTOHolder{events=13}] to queue [thinkbig.feed-manager]

2017-05-15 19:01:47,821 INFO [Timer-Driven Process Thread-10] c.t.n.p.j.ProvenanceEventActiveMqWriter SENDING AGGREGATED STAT to JMS AggregatedFeedProcessorStatisticsHolder{minTime=2017-05-15T19:01:40.872+08:00, maxTime=2017-05-15T19:01:42.774+08:00, collectionId='8085c9aa-5def-442a-85c3-72b2eb2d9634', eventCount=13} 

2017-05-15 19:01:47,821 INFO [Timer-Driven Process Thread-10] c.t.activemq.SendJmsMessage Sending ActiveMQ message [AggregatedFeedProcessorStatisticsHolder{minTime=2017-05-15T19:01:40.872+08:00, maxTime=2017-05-15T19:01:42.774+08:00, collectionId='8085c9aa-5def-442a-85c3-72b2eb2d9634', eventCount=13}] to queue [thinkbig.provenance-event-stats]

2017-05-15 19:01:47,824 INFO [Timer-Driven Process Thread-10] c.t.n.p.r.KyloProvenanceEventReportingTask KyloProvenanceEventReportingTask[id=07a2dee1-015c-1000-ab89-7a38f90158c7] ProvenanceEventPool: Pool Stats: Created:[15], Borrowed:[197]

2017-05-15 19:01:47,825 INFO [Timer-Driven Process Thread-10] c.t.n.p.r.KyloProvenanceEventReportingTask KyloProvenanceEventReportingTask[id=07a2dee1-015c-1000-ab89-7a38f90158c7] KyloProvenanceEventReportingTask onTrigger Info: ReportingTask finished. Last Event id: 2174422. Total time to process 13 events was 40 ms.  Total time spent querying for events in Nifi was 29 ms.  Kylo ProcessingTime: 11 ms 

2017-05-15 19:01:47,825 INFO [Timer-Driven Process Thread-10] c.t.n.p.r.KyloProvenanceEventReportingTask KyloProvenanceEventReportingTask[id=07a2dee1-015c-1000-ab89-7a38f90158c7] Reporting Task Finished.  Last Event Recorded was: 2174422 

2017-05-15 19:01:53,735 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Initiating checkpoint of FlowFile Repository

2017-05-15 19:01:53,776 INFO [pool-8-thread-1] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@7d197497 checkpointed with 5 Records and 0 Swap Files in 40 milliseconds (Stop-the-world time = 12 milliseconds, Clear Edit Logs time = 13 millis), max Transaction ID 1152863

2017-05-15 19:01:53,776 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Successfully checkpointed FlowFile Repository with 5 records in 40 milliseconds

2017-05-15 19:03:04,796 INFO [pool-21-thread-1] c.t.n.p.cache.FeedFlowFileGuavaCache FeedFlowFile Cache Size: 11  

2017-05-15 19:03:04,796 INFO [pool-21-thread-1] c.t.n.p.cache.FeedFlowFileGuavaCache ProvenanceEvent JMS Stats:  Sent 197 statistics events to JMS.  Sent 197 batch events to JMS 

2017-05-15 19:03:30,999 INFO [Write-Ahead Local State Provider Maintenance] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@322f1d97 checkpointed with 125 Records and 0 Swap Files in 7 milliseconds (Stop-the-world time = 1 milliseconds, Clear Edit Logs time = 0 millis), max Transaction ID 4788

2017-05-15 19:03:53,776 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Initiating checkpoint of FlowFile Repository

2017-05-15 19:03:53,819 INFO [pool-8-thread-1] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@7d197497 checkpointed with 5 Records and 0 Swap Files in 43 milliseconds (Stop-the-world time = 13 milliseconds, Clear Edit Logs time = 15 millis), max Transaction ID 1152871

2017-05-15 19:03:53,819 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Successfully checkpointed FlowFile Repository with 5 records in 43 milliseconds

2017-05-15 19:05:31,006 INFO [Write-Ahead Local State Provider Maintenance] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@322f1d97 checkpointed with 125 Records and 0 Swap Files in 7 milliseconds (Stop-the-world time = 0 milliseconds, Clear Edit Logs time = 0 millis), max Transaction ID 4788

2017-05-15 19:05:53,819 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Initiating checkpoint of FlowFile Repository

2017-05-15 19:05:53,870 INFO [pool-8-thread-1] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@7d197497 checkpointed with 5 Records and 0 Swap Files in 50 milliseconds (Stop-the-world time = 19 milliseconds, Clear Edit Logs time = 14 millis), max Transaction ID 1152879

2017-05-15 19:05:53,870 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Successfully checkpointed FlowFile Repository with 5 records in 50 milliseconds

2017-05-15 19:06:40,873 INFO [Timer-Driven Process Thread-6] c.t.nifi.v2.common.FeedProcessor Resolving ID for feed poc/test3

2017-05-15 19:06:40,896 INFO [Timer-Driven Process Thread-6] c.t.nifi.v2.common.FeedProcessor Resolving id 8f872775-897f-4f5b-9545-4542097c0dd6 for feed poc/test3

2017-05-15 19:07:31,013 INFO [Write-Ahead Local State Provider Maintenance] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@322f1d97 checkpointed with 125 Records and 0 Swap Files in 7 milliseconds (Stop-the-world time = 1 milliseconds, Clear Edit Logs time = 0 millis), max Transaction ID 4788

2017-05-15 19:07:53,870 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Initiating checkpoint of FlowFile Repository

2017-05-15 19:07:53,915 INFO [pool-8-thread-1] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@7d197497 checkpointed with 5 Records and 0 Swap Files in 44 milliseconds (Stop-the-world time = 13 milliseconds, Clear Edit Logs time = 14 millis), max Transaction ID 1152888

2017-05-15 19:07:53,915 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Successfully checkpointed FlowFile Repository with 5 records in 44 milliseconds

2017-05-15 19:08:14,796 INFO [pool-21-thread-1] c.t.n.p.cache.FeedFlowFileGuavaCache FeedFlowFile Cache Size: 11  

2017-05-15 19:08:14,796 INFO [pool-21-thread-1] c.t.n.p.cache.FeedFlowFileGuavaCache ProvenanceEvent JMS Stats:  Sent 197 statistics events to JMS.  Sent 197 batch events to JMS 

2017-05-15 19:09:31,021 INFO [Write-Ahead Local State Provider Maintenance] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@322f1d97 checkpointed with 125 Records and 0 Swap Files in 7 milliseconds (Stop-the-world time = 1 milliseconds, Clear Edit Logs time = 0 millis), max Transaction ID 4788

2017-05-15 19:09:53,915 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Initiating checkpoint of FlowFile Repository

2017-05-15 19:09:53,957 INFO [pool-8-thread-1] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@7d197497 checkpointed with 5 Records and 0 Swap Files in 42 milliseconds (Stop-the-world time = 12 milliseconds, Clear Edit Logs time = 14 millis), max Transaction ID 1152896

2017-05-15 19:09:53,958 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Successfully checkpointed FlowFile Repository with 5 records in 42 milliseconds

2017-05-15 19:11:31,028 INFO [Write-Ahead Local State Provider Maintenance] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@322f1d97 checkpointed with 125 Records and 0 Swap Files in 7 milliseconds (Stop-the-world time = 1 milliseconds, Clear Edit Logs time = 0 millis), max Transaction ID 4788

2017-05-15 19:11:41,897 INFO [Timer-Driven Process Thread-4] c.t.nifi.v2.common.FeedProcessor Resolving ID for feed poc/test3

2017-05-15 19:11:41,921 INFO [Timer-Driven Process Thread-4] c.t.nifi.v2.common.FeedProcessor Resolving id 8f872775-897f-4f5b-9545-4542097c0dd6 for feed poc/test3

2017-05-15 19:11:53,958 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Initiating checkpoint of FlowFile Repository

2017-05-15 19:11:54,001 INFO [pool-8-thread-1] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@7d197497 checkpointed with 5 Records and 0 Swap Files in 43 milliseconds (Stop-the-world time = 13 milliseconds, Clear Edit Logs time = 14 millis), max Transaction ID 1152905

2017-05-15 19:11:54,001 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Successfully checkpointed FlowFile Repository with 5 records in 43 milliseconds

2017-05-15 19:13:24,796 INFO [pool-21-thread-1] c.t.n.p.cache.FeedFlowFileGuavaCache FeedFlowFile Cache Size: 11  

2017-05-15 19:13:24,796 INFO [pool-21-thread-1] c.t.n.p.cache.FeedFlowFileGuavaCache ProvenanceEvent JMS Stats:  Sent 197 statistics events to JMS.  Sent 197 batch events to JMS 

2017-05-15 19:13:31,040 INFO [Write-Ahead Local State Provider Maintenance] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@322f1d97 checkpointed with 125 Records and 0 Swap Files in 11 milliseconds (Stop-the-world time = 1 milliseconds, Clear Edit Logs time = 0 millis), max Transaction ID 4788

2017-05-15 19:13:54,001 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Initiating checkpoint of FlowFile Repository

2017-05-15 19:13:54,063 INFO [pool-8-thread-1] org.wali.MinimalLockingWriteAheadLog org.wali.MinimalLockingWriteAheadLog@7d197497 checkpointed with 5 Records and 0 Swap Files in 61 milliseconds (Stop-the-world time = 20 milliseconds, Clear Edit Logs time = 14 millis), max Transaction ID 1152913

2017-05-15 19:13:54,063 INFO [pool-8-thread-1] o.a.n.c.r.WriteAheadFlowFileRepository Successfully checkpointed FlowFile Repository with 5 records in 61 milliseconds

[Greg Hart]

Hi Zhijia,

The most likely cause is that the Kylo Metadata Service controller service in NiFi is unable to communicate with Kylo. There are two places that must be changed: in the controller services for the root processor group, and in the Controller Services option under the hamburger menu in the top-right corner.

Thanks!

[zhijia lin]

Hi Greg,

Thanks your suggestion.  

After re-entering the password  for kylo meta service, it works now. 

seems the "nifi.service.kylo_metadata_service.rest_client_password=thinkbig"  doesnt work in kylo application.properties

nifi.service.kylo_metadata_service.rest_client_url=http://localhost:8400/proxy/v1/metadata

nifi.service.kylo_metadata_service.rest_client_password=thinkbig

Thanks!

[zhijia lin]

now failed at step 16 - profile data,  i can't find out the cause yet by checking the logs.

in  hadoop cluster - job history, it shows the Profiler is finished successfully.

The "Profile Data" processor in nifi is updated to use "yarn-cluster" according to "Tuning the ExecuteSparkJob Processor"  in troubleshooting section

kylo-spark-shell.err is attached for your reference, seems no error..

Any idea or suggestion to me?  thanks a ton!

[Greg Hart]

Hi Zhijia,

The properties in application.properties only affect new feeds. Since the Kylo Matadata Service was already created then it must be changed manually in NiFi.

For the profile data error, have you checked the NiFi logs to see if there's an error message in there?

Thanks!

[zhijia lin]

Thanks your suggestion. and i found below spark error in nifi log

Exception in thread "main" java.util.NoSuchElementException: 

at scala.collection.Iterator$$anon$2.next(Iterator.scala:39)

at scala.collection.Iterator$$anon$2.next(Iterator.scala:37)

and fixed it with 

1. On the edge node, edit the file: /usr/hdp/current/spark-client/conf/spark-defaults.conf
2. Add these configuration entries to the file:

spark.sql.hive.convertMetastoreOrc false
spark.sql.hive.convertMetastoreParquet false