Details
-
Type: Bug
-
Status: Closed
-
Priority: Minor
-
Resolution: Fixed
-
Affects Version/s: Rushmore
-
Fix Version/s: Mountain Dew
-
Component/s: Data Loader
-
Labels:None
-
Environment:
aml-merchant leads RC build
aml-merchant-leads-distribution-1.0.0-RC2-bin.tar.gz
-
Sprint:Sprint 1
Description
Continuous logging of error when there is a merchant ID that does not have an order deployed
Input file:
2015-04-14,Watermark03,501
Watermark03 is the Merchant ID which does not have an order in deployed state.
Log:
[TSAApp@aml-qa3-core1 aml-merchant-leads]$ tail -f aml-merchant-leads.log
[ main] SpringCamelContext INFO Apache Camel 2.14.1 (CamelContext: camel-1) is starting
[ main] ManagedManagementStrategy INFO JMX is enabled
[ main] DefaultTypeConverter INFO Loaded 178 type converters
[ main] SpringCamelContext INFO AllowUseOriginalMessage is enabled. If access to the original message is not needed, then its recommended to turn this option off as it may improve performance.
[ main] SpringCamelContext INFO StreamCaching is not in use. If using streams then its recommended to enable stream caching. See more details at http://camel.apache.org/stream-caching.html
[ main] SpringCamelContext INFO Route: leads-data-loader-exec started and consuming from: Endpointfile:///var/local/tsa/leads/transformed?delay=5000&doneFileName=%24%7Bfile%3Aname%7D-done.txt&exclude=.*%5C.camelLock&move=done
[ main] SpringCamelContext INFO Route: file-store started and consuming from: Endpointfile:///var/local/tsa/leads/tmp?delay=5000&exclude=.*%5C.camelLock&move=done
[ main] SpringCamelContext INFO Route: leads-csv-handler started and consuming from: Endpointfile:///var/local/tsa/leads/incoming?delay=5000&exclude=.*%5C.camelLock&move=done
[ main] SpringCamelContext INFO Total 3 routes, of which 3 is started.
[ main] SpringCamelContext INFO Apache Camel 2.14.1 (CamelContext: camel-1) started in 1.467 seconds
//var/local/tsa/leads/incoming leads-csv-handler INFO incoming file:
[call-leads-test-inputvarsh5.txt]
incoming data:
2015-04-14,Watermark03,501
//var/local/tsa/leads/incoming leads-csv-handler INFO row in: 2015-04-14,Watermark03,501
//var/local/tsa/leads/incoming leads-csv-handler INFO row out: 2015-04-14 153a875b-b6ba-4390-ac6d-4d294a47c522 501
[ar/local/tsa/leads/transformed] leads-data-loader-exec INFO Transformed File:
call-leads-test-inputvarsh5.txt
2015-04-14 153a875b-b6ba-4390-ac6d-4d294a47c522 501
[ar/local/tsa/leads/transformed] ExecProducer INFO Executing ExecCommand [args=[/var/local/tsa/config/com.thesearchagency.datafeeds.calldata.properties, /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt, 1], executable=/usr/local/tsa/bidmgr/leads-data-loader.sh, timeout=9223372036854775807, outFile=null, workingDir=null, useStderrOnEmptyStdout=false]
[ar/local/tsa/leads/transformed] ExecProducer INFO The command ExecCommand [args=[/var/local/tsa/config/com.thesearchagency.datafeeds.calldata.properties, /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt, 1], executable=/usr/local/tsa/bidmgr/leads-data-loader.sh, timeout=9223372036854775807, outFile=null, workingDir=null, useStderrOnEmptyStdout=false] had exit value 1
[ar/local/tsa/leads/transformed] ExecProducer ERROR The command ExecCommand [args=[/var/local/tsa/config/com.thesearchagency.datafeeds.calldata.properties, /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt, 1], executable=/usr/local/tsa/bidmgr/leads-data-loader.sh, timeout=9223372036854775807, outFile=null, workingDir=null, useStderrOnEmptyStdout=false] returned exit value 1
[ar/local/tsa/leads/transformed] leads-data-loader-exec INFO STDOUT:
[ar/local/tsa/leads/transformed] leads-data-loader-exec INFO STDERR: 2015-04-15 06:34:17.838 (3) [main]: Debug Level set to 4
2015-04-15 06:34:17.839 (3) [main]: Starting Data Loader. args [[/var/local/tsa/config/com.thesearchagency.datafeeds.calldata.properties, /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt, 1]]
2015-04-15 06:34:17.844 (3) [main]: ======== Starting Call Data Load ========
2015-04-15 06:34:17.845 (3) [main]: Loading filename: /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt
2015-04-15 06:34:17.945 (4) [main]: registered MBean [thesearchagency.db.util:type=MultiplexDatabasePool4150385c-4288-4864-aec2-9611d0924b2a] for class com.thesearchagency.db.util.MultiplexDatabasePool
2015-04-15 06:34:17.948 (4) [main]: no account, or instance for databaseInstance, skipping lookup...
2015-04-15 06:34:17.953 (4) [main]: registered MBean [com.carldunham.jst.pooling:type=ObjectPoolef2c6583-dc50-4d4d-bb7a-72a2ee0f053a] for class com.carldunham.jst.pooling.ObjectPool
2015-04-15 06:34:17.953 (3) [main]: DatabasePool with a limit of 80 created
2015-04-15 06:34:17.954 (4) [main]: registered MBean [com.carldunham.jst.db:type=DatabasePoolc17e4174-76c3-410d-885e-6076f5b03a16] for class com.carldunham.jst.db.DatabasePool
2015-04-15 06:34:17.967 (4) [ConnectionCloser]: Starting DatabasePool ConnectionCloserThread
2015-04-15 06:34:18.264 (3) [main]: JDBC Driver Version: 5.1 (com.mysql.jdbc.Driver)
2015-04-15 06:34:18.264 (4) [main]: opened [jdbc:mysql://tsacommon-01-write/tsacommon?useUnicode=true&zeroDateTimeBehavior=convertToNull&dontTrackOpenResources=true&jdbcCompliantTruncation=false&useServerPrepStmts=false&rewriteBatchedStatements=true]
2015-04-15 06:34:18.264 (4) [main]: Created new Object
2015-04-15 06:34:18.266 (4) [main]: spike: SQL->[select @@version]
2015-04-15 06:34:18.273 (4) [main]: time=0.0060
2015-04-15 06:34:18.273 (4) [main]: Query executed in 0.006s
2015-04-15 06:34:18.273 (4) [main]: test query succeeded, returned "5.5.33"
2015-04-15 06:34:18.273 (4) [main]: spike: SQL->[select id, description, databaseInstance from accounts where isActive = "true"]
2015-04-15 06:34:18.293 (4) [main]: time=0.02
2015-04-15 06:34:18.294 (4) [main]: Query executed in 0.020s
2015-04-15 06:34:18.358 (4) [main]: Returning Object to Pool
2015-04-15 06:34:18.360 (4) [main]: no account, or instance for databaseInstance, skipping lookup...
2015-04-15 06:34:18.360 (4) [main]: Took Existing Object from Pool
2015-04-15 06:34:18.360 (4) [main]: spike: SQL->[select @@version]
2015-04-15 06:34:18.362 (4) [main]: time=0.0020
2015-04-15 06:34:18.363 (4) [main]: Query executed in 0.002s
2015-04-15 06:34:18.363 (4) [main]: test query succeeded, returned "5.5.33"
2015-04-15 06:34:18.363 (4) [main]: preparing SQL statement [insert into callFeedExecution (fileName, runTimestamp, status) values (?, ?, ?) on duplicate key update runTimestamp=?, status=?, firstDate=null, lastDate=null, numDataLines=0, numDataLinesWithNegatives=0, numInvalidDataLines=0], genflags=yes
2015-04-15 06:34:18.377 (4) [main]: Returning Object to Pool
2015-04-15 06:34:18.380 (1) [main]: Could not find account [153a875b-b6ba-4390-ac6d-4d294a47c522]
2015-04-15 06:34:18.380 (2) [main]: WARNING:Account 153a875b-b6ba-4390-ac6d-4d294a47c522 not found.
2015-04-15 06:34:18.381 (1) [main]: Data rows in file (0) not equal to rows loaded in databse (0), manual intervention required
2015-04-15 06:34:18.381 (4) [main]: no account, or instance for databaseInstance, skipping lookup...
2015-04-15 06:34:18.381 (4) [main]: Took Existing Object from Pool
2015-04-15 06:34:18.381 (4) [main]: spike: SQL->[select @@version]
2015-04-15 06:34:18.384 (4) [main]: time=0.0030
2015-04-15 06:34:18.384 (4) [main]: Query executed in 0.003s
2015-04-15 06:34:18.384 (4) [main]: test query succeeded, returned "5.5.33"
2015-04-15 06:34:18.385 (4) [main]: preparing SQL statement [update callFeedExecution set firstDate=?, lastDate=?, numDataLines=?, numDataLinesWithNegatives=?, numInvalidDataLines=?, status=? where id=?]
2015-04-15 06:34:18.387 (4) [main]: Returning Object to Pool
2015-04-15 06:34:18.388 (3) [main]: Lines processed: 0
2015-04-15 06:34:18.388 (3) [main]: Invalid lines: 0
2015-04-15 06:34:18.388 (3) [main]: ======== Finished Call Data Load (FAILED) ========
2015-04-15 06:34:18.388 (1) [main]: Exited with non-zero exit code (exit code = 1). args [[/var/local/tsa/config/com.thesearchagency.datafeeds.calldata.properties, /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt, 1]]
[ar/local/tsa/leads/transformed] leads-data-loader-exec ERROR [ALERT] The leads data loading command failed. result is: 1
[ar/local/tsa/leads/transformed] leads-data-loader-exec ERROR [call-leads-test-inputvarsh5.txt] A copy of this file will be moved to /var/local/tsa/leads/error for troubleshooting.
[ar/local/tsa/leads/transformed] DefaultErrorHandler ERROR Failed delivery for (MessageId: ID-aml-qa3-core1-50324-1429079514655-0-8 on ExchangeId: ID-aml-qa3-core1-50324-1429079514655-0-9). Exhausted after delivery attempt: 1 caught: org.apache.camel.component.file.GenericFileOperationFailedException: Cannot store file: /var/local/tsa/leads/transformed/error/call-leads-test-inputvarsh5.txt
Message History
---------------------------------------------------------------------------------------------------------------------------------------
RouteId ProcessorId Processor Elapsed (ms)
[leads-data-loader-] [leads-data-loader-] file:///var/local/tsa/leads/transformed?delay=5000&doneFileName=%24%7Bfile%3An [ 786]
[leads-data-loader-] [log1 ] [log ] [ 1]
[leads-data-loader-] [setHeader1 ] [setHeader[CamelExecCommandArgs] ] [ 1]
[leads-data-loader-] [to1 ] [exec:///usr/local/tsa/bidmgr/leads-data-loader.sh ] [ 765]
[leads-data-loader-] [log2 ] [log ] [ 5]
[leads-data-loader-] [log3 ] [log ] [ 2]
[leads-data-loader-] [choice1 ] [when[simple{${body.getExitValue} == 0}]choice[] ] [ 21]
[leads-data-loader-] [log5 ] [log ] [ 1]
[leads-data-loader-] [log6 ] [log ] [ 0]
[leads-data-loader-] [to2 ] file:///var/local/tsa/leads/transformed/error [ 2]
Exchange
---------------------------------------------------------------------------------------------------------------------------------------
Exchange[
Id ID-aml-qa3-core1-50324-1429079514655-0-9
ExchangePattern InOnly
Headers
BodyType org.apache.camel.component.exec.ExecResult
Body org.apache.camel.component.exec.ExecResult@9bc850f
]
Stacktrace
---------------------------------------------------------------------------------------------------------------------------------------
org.apache.camel.component.file.GenericFileOperationFailedException: Cannot store file: /var/local/tsa/leads/transformed/error/call-leads-test-inputvarsh5.txt
at org.apache.camel.component.file.FileOperations.storeFile(FileOperations.java:278)
at org.apache.camel.component.file.GenericFileProducer.writeFile(GenericFileProducer.java:277)
at org.apache.camel.component.file.GenericFileProducer.processExchange(GenericFileProducer.java:165)
at org.apache.camel.component.file.GenericFileProducer.process(GenericFileProducer.java:79)
at org.apache.camel.util.AsyncProcessorConverterHelper$ProcessorToAsyncProcessorBridge.process(AsyncProcessorConverterHelper.java:61)
at org.apache.camel.processor.SendProcessor.process(SendProcessor.java:120)
at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:72)
at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:416)
at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:118)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:80)
at org.apache.camel.processor.ChoiceProcessor.process(ChoiceProcessor.java:111)
at org.apache.camel.management.InstrumentationProcessor.process(InstrumentationProcessor.java:72)
at org.apache.camel.processor.RedeliveryErrorHandler.process(RedeliveryErrorHandler.java:416)
at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:118)
at org.apache.camel.processor.Pipeline.process(Pipeline.java:80)
at org.apache.camel.processor.CamelInternalProcessor.process(CamelInternalProcessor.java:191)
at org.apache.camel.component.file.GenericFileConsumer.processExchange(GenericFileConsumer.java:433)
at org.apache.camel.component.file.GenericFileConsumer.processBatch(GenericFileConsumer.java:211)
at org.apache.camel.component.file.GenericFileConsumer.poll(GenericFileConsumer.java:175)
at org.apache.camel.impl.ScheduledPollConsumer.doRun(ScheduledPollConsumer.java:187)
at org.apache.camel.impl.ScheduledPollConsumer.run(ScheduledPollConsumer.java:114)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:180)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:204)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:662)
Caused by: org.apache.camel.InvalidPayloadException: No body available of type: java.io.InputStream but has value: org.apache.camel.component.exec.ExecResult@9bc850f of type: org.apache.camel.component.exec.ExecResult on: call-leads-test-inputvarsh5.txt. Caused by: No type converter available to convert from type: org.apache.camel.component.exec.ExecResult to the required type: java.io.InputStream with value org.apache.camel.component.exec.ExecResult@9bc850f. Exchange[call-leads-test-inputvarsh5.txt]. Caused by: [org.apache.camel.NoTypeConversionAvailableException - No type converter available to convert from type: org.apache.camel.component.exec.ExecResult to the required type: java.io.InputStream with value org.apache.camel.component.exec.ExecResult@9bc850f]
at org.apache.camel.impl.MessageSupport.getMandatoryBody(MessageSupport.java:101)
at org.apache.camel.component.file.FileOperations.storeFile(FileOperations.java:269)
... 31 more
Caused by: org.apache.camel.NoTypeConversionAvailableException: No type converter available to convert from type: org.apache.camel.component.exec.ExecResult to the required type: java.io.InputStream with value org.apache.camel.component.exec.ExecResult@9bc850f
at org.apache.camel.impl.converter.BaseTypeConverterRegistry.mandatoryConvertTo(BaseTypeConverterRegistry.java:182)
at org.apache.camel.impl.MessageSupport.getMandatoryBody(MessageSupport.java:99)
... 32 more
[ar/local/tsa/leads/transformed] GenericFileOnCompletion WARN Rollback file strategy: org.apache.camel.component.file.strategy.GenericFileRenameProcessStrategy@5262667 for file: GenericFile[/var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt]
[ar/local/tsa/leads/transformed] leads-data-loader-exec INFO Transformed File:
call-leads-test-inputvarsh5.txt
2015-04-14 153a875b-b6ba-4390-ac6d-4d294a47c522 501
[ar/local/tsa/leads/transformed] ExecProducer INFO Executing ExecCommand [args=[/var/local/tsa/config/com.thesearchagency.datafeeds.calldata.properties, /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt, 1], executable=/usr/local/tsa/bidmgr/leads-data-loader.sh, timeout=9223372036854775807, outFile=null, workingDir=null, useStderrOnEmptyStdout=false]
[ar/local/tsa/leads/transformed] ExecProducer INFO The command ExecCommand [args=[/var/local/tsa/config/com.thesearchagency.datafeeds.calldata.properties, /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt, 1], executable=/usr/local/tsa/bidmgr/leads-data-loader.sh, timeout=9223372036854775807, outFile=null, workingDir=null, useStderrOnEmptyStdout=false] had exit value 1
[ar/local/tsa/leads/transformed] ExecProducer ERROR The command ExecCommand [args=[/var/local/tsa/config/com.thesearchagency.datafeeds.calldata.properties, /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt, 1], executable=/usr/local/tsa/bidmgr/leads-data-loader.sh, timeout=9223372036854775807, outFile=null, workingDir=null, useStderrOnEmptyStdout=false] returned exit value 1
[ar/local/tsa/leads/transformed] leads-data-loader-exec INFO STDOUT:
[ar/local/tsa/leads/transformed] leads-data-loader-exec INFO STDERR: 2015-04-15 06:34:23.629 (3) [main]: Debug Level set to 4
2015-04-15 06:34:23.630 (3) [main]: Starting Data Loader. args [[/var/local/tsa/config/com.thesearchagency.datafeeds.calldata.properties, /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt, 1]]
2015-04-15 06:34:23.635 (3) [main]: ======== Starting Call Data Load ========
2015-04-15 06:34:23.636 (3) [main]: Loading filename: /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt
2015-04-15 06:34:23.716 (4) [main]: registered MBean [thesearchagency.db.util:type=MultiplexDatabasePool91ec55da-6a6d-48aa-842c-ee3438bb5572] for class com.thesearchagency.db.util.MultiplexDatabasePool
2015-04-15 06:34:23.725 (4) [main]: no account, or instance for databaseInstance, skipping lookup...
2015-04-15 06:34:23.729 (4) [main]: registered MBean [com.carldunham.jst.pooling:type=ObjectPool1ca27730-97b9-4071-9b21-89d2073ab0ed] for class com.carldunham.jst.pooling.ObjectPool
2015-04-15 06:34:23.729 (3) [main]: DatabasePool with a limit of 80 created
2015-04-15 06:34:23.730 (4) [main]: registered MBean [com.carldunham.jst.db:type=DatabasePoold8d3dee7-d1bd-486e-90d6-82930cafcd0f] for class com.carldunham.jst.db.DatabasePool
2015-04-15 06:34:23.732 (4) [ConnectionCloser]: Starting DatabasePool ConnectionCloserThread
2015-04-15 06:34:24.006 (3) [main]: JDBC Driver Version: 5.1 (com.mysql.jdbc.Driver)
2015-04-15 06:34:24.006 (4) [main]: opened [jdbc:mysql://tsacommon-01-write/tsacommon?useUnicode=true&zeroDateTimeBehavior=convertToNull&dontTrackOpenResources=true&jdbcCompliantTruncation=false&useServerPrepStmts=false&rewriteBatchedStatements=true]
2015-04-15 06:34:24.007 (4) [main]: Created new Object
2015-04-15 06:34:24.009 (4) [main]: spike: SQL->[select @@version]
2015-04-15 06:34:24.016 (4) [main]: time=0.0070
2015-04-15 06:34:24.016 (4) [main]: Query executed in 0.007s
2015-04-15 06:34:24.017 (4) [main]: test query succeeded, returned "5.5.33"
2015-04-15 06:34:24.017 (4) [main]: spike: SQL->[select id, description, databaseInstance from accounts where isActive = "true"]
2015-04-15 06:34:24.037 (4) [main]: time=0.02
2015-04-15 06:34:24.037 (4) [main]: Query executed in 0.020s
2015-04-15 06:34:24.095 (4) [main]: Returning Object to Pool
2015-04-15 06:34:24.097 (4) [main]: no account, or instance for databaseInstance, skipping lookup...
2015-04-15 06:34:24.097 (4) [main]: Took Existing Object from Pool
2015-04-15 06:34:24.098 (4) [main]: spike: SQL->[select @@version]
2015-04-15 06:34:24.100 (4) [main]: time=0.0020
2015-04-15 06:34:24.100 (4) [main]: Query executed in 0.002s
2015-04-15 06:34:24.100 (4) [main]: test query succeeded, returned "5.5.33"
2015-04-15 06:34:24.101 (4) [main]: preparing SQL statement [insert into callFeedExecution (fileName, runTimestamp, status) values (?, ?, ?) on duplicate key update runTimestamp=?, status=?, firstDate=null, lastDate=null, numDataLines=0, numDataLinesWithNegatives=0, numInvalidDataLines=0], genflags=yes
2015-04-15 06:34:24.114 (4) [main]: Returning Object to Pool
2015-04-15 06:34:24.117 (1) [main]: Could not find account [153a875b-b6ba-4390-ac6d-4d294a47c522]
2015-04-15 06:34:24.117 (2) [main]: WARNING:Account 153a875b-b6ba-4390-ac6d-4d294a47c522 not found.
2015-04-15 06:34:24.118 (1) [main]: Data rows in file (0) not equal to rows loaded in databse (0), manual intervention required
2015-04-15 06:34:24.118 (4) [main]: no account, or instance for databaseInstance, skipping lookup...
2015-04-15 06:34:24.118 (4) [main]: Took Existing Object from Pool
2015-04-15 06:34:24.118 (4) [main]: spike: SQL->[select @@version]
2015-04-15 06:34:24.121 (4) [main]: time=0.0030
2015-04-15 06:34:24.121 (4) [main]: Query executed in 0.003s
2015-04-15 06:34:24.121 (4) [main]: test query succeeded, returned "5.5.33"
2015-04-15 06:34:24.121 (4) [main]: preparing SQL statement [update callFeedExecution set firstDate=?, lastDate=?, numDataLines=?, numDataLinesWithNegatives=?, numInvalidDataLines=?, status=? where id=?]
2015-04-15 06:34:24.124 (4) [main]: Returning Object to Pool
2015-04-15 06:34:24.124 (3) [main]: Lines processed: 0
2015-04-15 06:34:24.124 (3) [main]: Invalid lines: 0
2015-04-15 06:34:24.124 (3) [main]: ======== Finished Call Data Load (FAILED) ========
2015-04-15 06:34:24.124 (1) [main]: Exited with non-zero exit code (exit code = 1). args [[/var/local/tsa/config/com.thesearchagency.datafeeds.calldata.properties, /var/local/tsa/leads/transformed/call-leads-test-inputvarsh5.txt, 1]]
This logging process never stops until merchant leads is stopped.