Can't start ice reader about ice HOT 7 CLOSED

@nmcserra I have never seen this error. It feels like something is wrong with the s3 bucket. What value do you have for ice.work_s3bucketprefix? What files did you see got created by Ice writer?

Are you sharing the bucket with other programs? If the problem still exists, can you create a new bucket for Ice?

from ice.

Hi,

I didn't specify any, left it empty:

ice.work_s3bucketprefix=

These are the files the processor created in the S3 bucket, different sizes, none empty:

cost_daily_all_2013
cost_hourly_all_2013-4
cost_hourly_all_2013-5
cost_hourly_all_2013-6
cost_hourly_all_2013-7
cost_hourly_all_2013-8
cost_montly_all
cost_weekly_all
lastProcessMillis2013-4
lastProcessMillis2013-5
lastProcessMillis2013-6
lastProcessMillis2013-7
lastProcessMillis2013-8
reservation_prices.threeyear.HEAVY
tagdb_all
usage_daily_all_2013
usage_hourly_all_2013-4
usage_hourly_all_2013-5
usage_hourly_all_2013-6
usage_hourly_all_2013-7
usage_hourly_all_2013-8
usage_monthly_all
usage_yearly_all

The work bucket specification is a subfolder of the billing bucket, I wonder if that's what's causing the problems:

ice.billing_s3bucketname=
ice.work_s3bucketname=/ice_processor

We're not sharing with other programs; I'll try putting the work bucket in its own bucket and see what happens.

I went back to the processor logs and found some errors too. For each new month it spews out this error:

| Error 2013-08-23 18:27:49,330 [com.netflix.ice.processor.BillingFileProcessor] ERROR processor.BillingFileProcessor - Error reading from file lastProcessMillis_2013-08
Message: The specified key does not exist.
Line | Method
->> 644 | handleErrorResponse in com.amazonaws.http.AmazonHttpClient

| 338 | executeHelper in ''
| 190 | execute . . . . . . in ''
| 2979 | invoke in com.amazonaws.services.s3.AmazonS3Client
| 911 | getObject . . . . . in ''
| 801 | getObject in ''
| 791 | getLastMillis . . . in com.netflix.ice.processor.BillingFileProcessor
| 805 | lastProcessTime in ''
| 151 | poll . . . . . . . in ''
| 50 | doWork in com.netflix.ice.common.Poller
| 28 | access$000 . . . . in ''
| 88 | run in com.netflix.ice.common.Poller$1
^ 724 | run . . . . . . . . in java.lang.Thread
2013-08-23 18:27:49,371 [com.netflix.ice.processor.BillingFileProcessor] INFO processor.BillingFileProcessor - trying to download 175967035865-aws-billing-detailed-line-items-2013-08.csv.zip...
2013-08-23 18:27:51,196 [com.netflix.ice.processor.BillingFileProcessor] INFO processor.BillingFileProcessor - downloaded 175967035865-aws-billing-detailed-line-items-2013-08.csv.zip
2013-08-23 18:27:51,196 [com.netflix.ice.processor.BillingFileProcessor] INFO processor.BillingFileProcessor - processing 175967035865-aws-billing-detailed-line-items-2013-08.csv.zip...
...etc. (it just carries on, no more errors).

It doesn't happen in subsequent runs of the processor, seems to be only the first time it processes a new month/file.

from ice.

@nmcserra ice.work_s3bucketname must be the bucket name. I wonder how did the processor managed to write files to s3 bucket at the first place...

from ice.

You underestimate the code :) So it looks much better now after setting up the worker bucket on a new bucket, but now I'm getting java out of memory errors - I tried increasing the heap size with JAVACMD_OPTS -Xxmx , but didn't seem to fix it. I notice some "null" messages like:

INFO reader.ReaderConfig - found 744 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798

I guess it could be a configuration issue (I didn't look into the account aliases, etc. yet) or a problem with the data files?

Full log below:

| Running Grails application
2013-08-27 19:53:00,717 [main] INFO http11.Http11Protocol - Initializing ProtocolHandler ["http-bio-8080"]
2013-08-27 19:53:00,752 [main] INFO core.StandardService - Starting service Tomcat
2013-08-27 19:53:00,752 [main] INFO core.StandardEngine - Starting Servlet Engine: Apache Tomcat/7.0.30
2013-08-27 19:53:00,902 [localhost-startStop-1] INFO startup.ContextConfig - No global web.xml found
2013-08-27 19:53:01,099 [localhost-startStop-1] INFO [localhost].[/ice] - Initializing Spring root WebApplicationContext
2013-08-27 19:53:07,633 [localhost-startStop-1] INFO scaffolding.DefaultGrailsTemplateGenerator - Scaffolding template generator set to use resource loader org.codehaus.groovy.grails.commons.spring.GrailsWebApplicationContext@47ff07ce: startup date [Tue Aug 27 19:53:05 BST 2013]; parent: Root WebApplicationContext
2013-08-27 19:53:10,193 [localhost-startStop-1] INFO context.GrailsConfigUtils - [GrailsContextLoader] Grails application loaded.
2013-08-27 19:53:10,247 [localhost-startStop-1] INFO BootStrap - Starting ice...
2013-08-27 19:53:11,214 [localhost-startStop-1] INFO basic.BasicManagers - trying to find new tag group and data managers...
2013-08-27 19:53:12,809 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/tagdb_all 1377627332000 1377627782000
2013-08-27 19:53:12,809 [localhost-startStop-1] INFO basic.BasicTagGroupManager - trying to read from /home/ice/ice_reader/tagdb_all
2013-08-27 19:53:17,723 [localhost-startStop-1] INFO basic.BasicTagGroupManager - done reading /home/ice/ice_reader/tagdb_all
2013-08-27 19:53:17,726 [localhost-startStop-1] INFO basic.BasicTagGroupManager - poller thread for tagdb_all started...
2013-08-27 19:53:17,727 [tagdb_all] INFO basic.BasicTagGroupManager - poller starting...
2013-08-27 19:53:17,769 [tagdb_all] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/tagdb_all 1377627332000 1377627782000
2013-08-27 19:53:17,789 [localhost-startStop-1] INFO basic.BasicDataManager - poller thread for cost_hourly_all started...
2013-08-27 19:53:17,790 [cost_hourly_all] INFO basic.BasicDataManager - poller starting...
2013-08-27 19:53:17,790 [localhost-startStop-1] INFO basic.BasicDataManager - poller thread for usage_hourly_all started...
2013-08-27 19:53:17,790 [cost_hourly_all] INFO basic.BasicDataManager - cost_hourly_all start polling...
2013-08-27 19:53:17,791 [usage_hourly_all] INFO basic.BasicDataManager - poller starting...
2013-08-27 19:53:17,791 [usage_hourly_all] INFO basic.BasicDataManager - usage_hourly_all start polling...
2013-08-27 19:53:17,791 [cost_daily_all] INFO basic.BasicDataManager - poller starting...
2013-08-27 19:53:17,792 [cost_daily_all] INFO basic.BasicDataManager - cost_daily_all start polling...
2013-08-27 19:53:17,791 [localhost-startStop-1] INFO basic.BasicDataManager - poller thread for cost_daily_all started...
2013-08-27 19:53:17,792 [localhost-startStop-1] INFO basic.BasicDataManager - poller thread for usage_daily_all started...
2013-08-27 19:53:17,792 [usage_daily_all] INFO basic.BasicDataManager - poller starting...
2013-08-27 19:53:17,793 [localhost-startStop-1] INFO basic.BasicDataManager - poller thread for cost_weekly_all started...
2013-08-27 19:53:17,793 [usage_daily_all] INFO basic.BasicDataManager - usage_daily_all start polling...
2013-08-27 19:53:17,793 [localhost-startStop-1] INFO basic.BasicDataManager - poller thread for usage_weekly_all started...
2013-08-27 19:53:17,793 [usage_weekly_all] INFO basic.BasicDataManager - poller starting...
2013-08-27 19:53:17,793 [usage_weekly_all] INFO basic.BasicDataManager - usage_weekly_all start polling...
2013-08-27 19:53:17,794 [localhost-startStop-1] INFO basic.BasicDataManager - poller thread for cost_monthly_all started...
2013-08-27 19:53:17,794 [cost_monthly_all] INFO basic.BasicDataManager - poller starting...
2013-08-27 19:53:17,794 [cost_monthly_all] INFO basic.BasicDataManager - cost_monthly_all start polling...
2013-08-27 19:53:17,794 [cost_weekly_all] INFO basic.BasicDataManager - poller starting...
2013-08-27 19:53:17,796 [usage_monthly_all] INFO basic.BasicDataManager - poller starting...
2013-08-27 19:53:17,794 [localhost-startStop-1] INFO basic.BasicDataManager - poller thread for usage_monthly_all started...
2013-08-27 19:53:17,796 [cost_weekly_all] INFO basic.BasicDataManager - cost_weekly_all start polling...
2013-08-27 19:53:17,796 [localhost-startStop-1] INFO basic.BasicManagers - poller thread for com.netflix.ice.basic.BasicManagers started...
2013-08-27 19:53:17,797 [usage_monthly_all] INFO basic.BasicDataManager - usage_monthly_all start polling...
2013-08-27 19:53:17,800 [com.netflix.ice.basic.BasicManagers] INFO basic.BasicManagers - poller starting...
2013-08-27 19:53:17,810 [com.netflix.ice.basic.BasicManagers] INFO basic.BasicManagers - trying to find new tag group and data managers...
2013-08-27 19:53:17,888 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/cost_hourly_all_2013-04 1377626226000 1377627789000
2013-08-27 19:53:17,888 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/cost_hourly_all_2013-04
2013-08-27 19:53:33,667 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/cost_hourly_all_2013-04
2013-08-27 19:53:33,673 [localhost-startStop-1] INFO reader.ReaderConfig - found 720 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798
2013-08-27 19:53:33,755 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/cost_hourly_all_2013-05 1377626523000 1377627810000
2013-08-27 19:53:33,756 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/cost_hourly_all_2013-05
2013-08-27 19:53:50,974 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/cost_hourly_all_2013-05
2013-08-27 19:53:50,974 [localhost-startStop-1] INFO reader.ReaderConfig - found 744 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798
2013-08-27 19:53:51,057 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/cost_hourly_all_2013-06 1377626857000 1377627831000
2013-08-27 19:53:51,057 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/cost_hourly_all_2013-06
2013-08-27 19:54:09,935 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/cost_hourly_all_2013-06
2013-08-27 19:54:09,936 [localhost-startStop-1] INFO reader.ReaderConfig - found 720 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798
2013-08-27 19:54:10,036 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/cost_hourly_all_2013-07 1377627240000 1377627853000
2013-08-27 19:54:10,036 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/cost_hourly_all_2013-07
2013-08-27 19:54:29,756 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/cost_hourly_all_2013-07
2013-08-27 19:54:29,757 [localhost-startStop-1] INFO reader.ReaderConfig - found 744 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798
2013-08-27 19:54:29,834 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/cost_hourly_all_2013-08 1377627601000 1377627877000
2013-08-27 19:54:29,835 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/cost_hourly_all_2013-08
2013-08-27 19:54:46,447 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/cost_hourly_all_2013-08
2013-08-27 19:54:46,448 [localhost-startStop-1] INFO reader.ReaderConfig - found 626 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798
2013-08-27 19:54:46,530 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/usage_hourly_all_2013-04 1377626166000 1377627897000
2013-08-27 19:54:46,531 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/usage_hourly_all_2013-04
2013-08-27 19:55:02,341 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/usage_hourly_all_2013-04
2013-08-27 19:55:02,341 [localhost-startStop-1] INFO reader.ReaderConfig - found 720 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798
2013-08-27 19:55:02,421 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/usage_hourly_all_2013-05 1377626457000 1377627916000
2013-08-27 19:55:02,421 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/usage_hourly_all_2013-05
2013-08-27 19:55:20,757 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/usage_hourly_all_2013-05
2013-08-27 19:55:20,758 [localhost-startStop-1] INFO reader.ReaderConfig - found 744 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798
2013-08-27 19:55:20,842 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/usage_hourly_all_2013-06 1377626787000 1377627938000
2013-08-27 19:55:20,842 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/usage_hourly_all_2013-06
2013-08-27 19:55:38,670 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/usage_hourly_all_2013-06
2013-08-27 19:55:38,670 [localhost-startStop-1] INFO reader.ReaderConfig - found 720 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798
2013-08-27 19:55:38,747 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/usage_hourly_all_2013-07 1377627164000 1377627959000
2013-08-27 19:55:38,747 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/usage_hourly_all_2013-07
2013-08-27 19:55:59,151 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/usage_hourly_all_2013-07
2013-08-27 19:55:59,151 [localhost-startStop-1] INFO reader.ReaderConfig - found 744 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798
2013-08-27 19:55:59,229 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/usage_hourly_all_2013-08 1377627538000 1377627984000
2013-08-27 19:55:59,229 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/usage_hourly_all_2013-08
2013-08-27 19:56:16,370 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/usage_hourly_all_2013-08
2013-08-27 19:56:16,370 [localhost-startStop-1] INFO reader.ReaderConfig - found 626 hours data for null 2013-04-01T00:00:00.000/2013-08-27T18:53:17.798
2013-08-27 19:56:16,452 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/cost_daily_all_2013 1377627471000 1377628004000
2013-08-27 19:56:16,452 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/cost_daily_all_2013
2013-08-27 19:56:22,075 [localhost-startStop-1] INFO basic.BasicDataManager - done loading data from /home/ice/ice_reader/cost_daily_all_2013
2013-08-27 19:56:22,160 [localhost-startStop-1] INFO common.AwsUtils - downloadFileIfChanged /home/ice/ice_reader/usage_daily_all_2013 1377627406000 1377628521000
2013-08-27 19:56:22,160 [localhost-startStop-1] INFO basic.BasicDataManager - trying to load data from /home/ice/ice_reader/usage_daily_all_2013
| Error 2013-08-27 19:56:29,833 [localhost-startStop-1] ERROR context.GrailsContextLoader - Error initializing the application: com.google.common.util.concurrent.ExecutionError: java.lang.OutOfMemoryError: Java heap space
Message: com.google.common.util.concurrent.ExecutionError: java.lang.OutOfMemoryError: Java heap space
Line | Method
->> 308 | evaluateEnvironmentSpecificBlock in grails.util.Environment

| 301 | executeForEnvironment in ''
| 277 | executeForCurrentEnvironment . . in ''
| 334 | innerRun in java.util.concurrent.FutureTask$Sync
| 166 | run . . . . . . . . . . . . . . in java.util.concurrent.FutureTask
| 1145 | runWorker in java.util.concurrent.ThreadPoolExecutor
| 615 | run . . . . . . . . . . . . . . in java.util.concurrent.ThreadPoolExecutor$Worker
^ 724 | run in java.lang.Thread

Caused by ExecutionError: java.lang.OutOfMemoryError: Java heap space
->> 2261 | get in com.google.common.cache.LocalCache$Segment

| 4000 | get in com.google.common.cache.LocalCache
| 4004 | getOrLoad . . . . . . . . . . . in ''
| 4874 | get in com.google.common.cache.LocalCache$LocalLoadingCache
| 167 | getReadOnlyData . . . . . . . . in com.netflix.ice.basic.BasicDataManager
| 316 | getDataLength in ''
| 152 | readData . . . . . . . . . . . . in com.netflix.ice.reader.ReaderConfig
| 123 | start in ''
| 205 | doCall . . . . . . . . . . . . . in BootStrap$_closure1
| 308 | evaluateEnvironmentSpecificBlock in grails.util.Environment
| 301 | executeForEnvironment . . . . . in ''
| 277 | executeForCurrentEnvironment in ''
| 334 | innerRun . . . . . . . . . . . . in java.util.concurrent.FutureTask$Sync
| 166 | run in java.util.concurrent.FutureTask
| 1145 | runWorker . . . . . . . . . . . in java.util.concurrent.ThreadPoolExecutor
| 615 | run in java.util.concurrent.ThreadPoolExecutor$Worker
^ 724 | run . . . . . . . . . . . . . . in java.lang.Thread

Caused by OutOfMemoryError: Java heap space
->> 62 | deserialize in com.netflix.ice.reader.ReadOnlyData$Serializer

| 156 | loadDataFromFile in com.netflix.ice.basic.BasicDataManager
| 106 | loadData . . . . . . . . . . . . in ''
| 42 | access$000 in ''
| 61 | load . . . . . . . . . . . . . . in com.netflix.ice.basic.BasicDataManager$1
| 59 | load in ''
| 3599 | loadFuture . . . . . . . . . . . in com.google.common.cache.LocalCache$LoadingValueReference
| 2379 | loadSync in com.google.common.cache.LocalCache$Segment
| 2342 | lockedGetOrLoad . . . . . . . . in ''
| 2257 | get in ''
| 4000 | get . . . . . . . . . . . . . . in com.google.common.cache.LocalCache
| 4004 | getOrLoad in ''
| 4874 | get . . . . . . . . . . . . . . in com.google.common.cache.LocalCache$LocalLoadingCache
| 167 | getReadOnlyData in com.netflix.ice.basic.BasicDataManager
| 316 | getDataLength . . . . . . . . . in ''
| 152 | readData in com.netflix.ice.reader.ReaderConfig
| 123 | start . . . . . . . . . . . . . in ''
^ 205 | doCall in BootStrap$_closure1

from ice.

@nmcserra your logs look fine to me. How big is your heap?

from ice.

-Xmx100m should be fine on a t1.micro. We have several Ice deployments running on this setup without OutOfMemory errors and without the JVM being killed for excess memory consumption.

from ice.

Thanks for all the help, it's all good now. I eventually edited GRAILS_OPTS in grailsw and raised the max heap size to 1G and the error went away (My other attempts to raise the max heap size through env. variables were not taking effect). We have a gazillion accounts so I guess it could lead to high memory utilisation, I'll see about tuning it down later.

from ice.