Model Loader error

[harrywang]

I have OAE running locally - everything is fine. The following commands were used:

node generate.js -b 1 -t tenant1 -u 1000 to generate -g 2000 to generate -c 10000 -d 1000
npm install
node loaddata.js -b -h http://tenant1.oae.com

Error after creating 50 followers:

roaming-217-62:OAE-model-loader harrywang$ node loaddata.js -b -h http://tenant1.oae.com
Loading Batch 0
Thu, 13 Nov 2014 23:31:44 GMT: Finished Loading User 0 of 1000
Thu, 13 Nov 2014 23:31:46 GMT: Finished Loading User 10 of 1000
Thu, 13 Nov 2014 23:31:47 GMT: Finished Loading User 20 of 1000
Thu, 13 Nov 2014 23:31:49 GMT: Finished Loading User 30 of 1000
Thu, 13 Nov 2014 23:31:50 GMT: Finished Loading User 40 of 1000
Thu, 13 Nov 2014 23:31:52 GMT: Finished Loading User 50 of 1000
Thu, 13 Nov 2014 23:31:53 GMT: Finished Loading User 60 of 1000
Thu, 13 Nov 2014 23:31:54 GMT: Finished Loading User 70 of 1000
Thu, 13 Nov 2014 23:31:56 GMT: Finished Loading User 80 of 1000
Thu, 13 Nov 2014 23:31:57 GMT: Finished Loading User 90 of 1000
Thu, 13 Nov 2014 23:31:59 GMT: Finished Loading User 100 of 1000
Thu, 13 Nov 2014 23:32:00 GMT: Finished Loading User 110 of 1000
Thu, 13 Nov 2014 23:32:02 GMT: Finished Loading User 120 of 1000
Thu, 13 Nov 2014 23:32:03 GMT: Finished Loading User 130 of 1000
Thu, 13 Nov 2014 23:32:05 GMT: Finished Loading User 140 of 1000
Thu, 13 Nov 2014 23:32:06 GMT: Finished Loading User 150 of 1000
Thu, 13 Nov 2014 23:32:08 GMT: Finished Loading User 160 of 1000
Thu, 13 Nov 2014 23:32:09 GMT: Finished Loading User 170 of 1000
Thu, 13 Nov 2014 23:32:11 GMT: Finished Loading User 180 of 1000
Thu, 13 Nov 2014 23:32:12 GMT: Finished Loading User 190 of 1000
Thu, 13 Nov 2014 23:32:14 GMT: Finished Loading User 200 of 1000
Thu, 13 Nov 2014 23:32:15 GMT: Finished Loading User 210 of 1000
Thu, 13 Nov 2014 23:32:17 GMT: Finished Loading User 220 of 1000
Thu, 13 Nov 2014 23:32:18 GMT: Finished Loading User 230 of 1000
Thu, 13 Nov 2014 23:32:20 GMT: Finished Loading User 240 of 1000
Thu, 13 Nov 2014 23:32:21 GMT: Finished Loading User 250 of 1000
Thu, 13 Nov 2014 23:32:23 GMT: Finished Loading User 260 of 1000
Thu, 13 Nov 2014 23:32:24 GMT: Finished Loading User 270 of 1000
Thu, 13 Nov 2014 23:32:26 GMT: Finished Loading User 280 of 1000
Thu, 13 Nov 2014 23:32:28 GMT: Finished Loading User 290 of 1000
Thu, 13 Nov 2014 23:32:29 GMT: Finished Loading User 300 of 1000
Thu, 13 Nov 2014 23:32:31 GMT: Finished Loading User 310 of 1000
Thu, 13 Nov 2014 23:32:33 GMT: Finished Loading User 320 of 1000
Thu, 13 Nov 2014 23:32:34 GMT: Finished Loading User 330 of 1000
Thu, 13 Nov 2014 23:32:36 GMT: Finished Loading User 340 of 1000
Thu, 13 Nov 2014 23:32:38 GMT: Finished Loading User 350 of 1000
Thu, 13 Nov 2014 23:32:39 GMT: Finished Loading User 360 of 1000
Thu, 13 Nov 2014 23:32:41 GMT: Finished Loading User 370 of 1000
Thu, 13 Nov 2014 23:32:42 GMT: Finished Loading User 380 of 1000
Thu, 13 Nov 2014 23:32:44 GMT: Finished Loading User 390 of 1000
Thu, 13 Nov 2014 23:32:46 GMT: Finished Loading User 400 of 1000
Thu, 13 Nov 2014 23:32:48 GMT: Finished Loading User 410 of 1000
Thu, 13 Nov 2014 23:32:49 GMT: Finished Loading User 420 of 1000
Thu, 13 Nov 2014 23:32:50 GMT: Finished Loading User 430 of 1000
Thu, 13 Nov 2014 23:32:51 GMT: Finished Loading User 440 of 1000
Thu, 13 Nov 2014 23:32:53 GMT: Finished Loading User 450 of 1000
Thu, 13 Nov 2014 23:32:54 GMT: Finished Loading User 460 of 1000
Thu, 13 Nov 2014 23:32:56 GMT: Finished Loading User 470 of 1000
Thu, 13 Nov 2014 23:32:58 GMT: Finished Loading User 480 of 1000
Thu, 13 Nov 2014 23:33:00 GMT: Finished Loading User 490 of 1000
Thu, 13 Nov 2014 23:33:01 GMT: Finished Loading User 500 of 1000
Thu, 13 Nov 2014 23:33:03 GMT: Finished Loading User 510 of 1000
Thu, 13 Nov 2014 23:33:05 GMT: Finished Loading User 520 of 1000
Thu, 13 Nov 2014 23:33:07 GMT: Finished Loading User 530 of 1000
Thu, 13 Nov 2014 23:33:08 GMT: Finished Loading User 540 of 1000
Thu, 13 Nov 2014 23:33:10 GMT: Finished Loading User 550 of 1000
Thu, 13 Nov 2014 23:33:12 GMT: Finished Loading User 560 of 1000
Thu, 13 Nov 2014 23:33:14 GMT: Finished Loading User 570 of 1000
Thu, 13 Nov 2014 23:33:15 GMT: Finished Loading User 580 of 1000
Thu, 13 Nov 2014 23:33:17 GMT: Finished Loading User 590 of 1000
Thu, 13 Nov 2014 23:33:19 GMT: Finished Loading User 600 of 1000
Thu, 13 Nov 2014 23:33:20 GMT: Finished Loading User 610 of 1000
Thu, 13 Nov 2014 23:33:21 GMT: Finished Loading User 620 of 1000
Thu, 13 Nov 2014 23:33:23 GMT: Finished Loading User 630 of 1000
Thu, 13 Nov 2014 23:33:25 GMT: Finished Loading User 640 of 1000
Thu, 13 Nov 2014 23:33:26 GMT: Finished Loading User 650 of 1000
Thu, 13 Nov 2014 23:33:28 GMT: Finished Loading User 660 of 1000
Thu, 13 Nov 2014 23:33:30 GMT: Finished Loading User 670 of 1000
Thu, 13 Nov 2014 23:33:32 GMT: Finished Loading User 680 of 1000
Thu, 13 Nov 2014 23:33:32 GMT: Finished Loading User 690 of 1000
Thu, 13 Nov 2014 23:33:35 GMT: Finished Loading User 700 of 1000
Thu, 13 Nov 2014 23:33:36 GMT: Finished Loading User 710 of 1000
Thu, 13 Nov 2014 23:33:37 GMT: Finished Loading User 720 of 1000
Thu, 13 Nov 2014 23:33:39 GMT: Finished Loading User 730 of 1000
Thu, 13 Nov 2014 23:33:40 GMT: Finished Loading User 740 of 1000
Thu, 13 Nov 2014 23:33:41 GMT: Finished Loading User 750 of 1000
Thu, 13 Nov 2014 23:33:43 GMT: Finished Loading User 760 of 1000
Thu, 13 Nov 2014 23:33:44 GMT: Finished Loading User 770 of 1000
Thu, 13 Nov 2014 23:33:46 GMT: Finished Loading User 780 of 1000
Thu, 13 Nov 2014 23:33:47 GMT: Finished Loading User 790 of 1000
Thu, 13 Nov 2014 23:33:49 GMT: Finished Loading User 800 of 1000
Thu, 13 Nov 2014 23:33:51 GMT: Finished Loading User 810 of 1000
Thu, 13 Nov 2014 23:33:53 GMT: Finished Loading User 820 of 1000
Thu, 13 Nov 2014 23:33:54 GMT: Finished Loading User 830 of 1000
Thu, 13 Nov 2014 23:33:56 GMT: Finished Loading User 840 of 1000
Thu, 13 Nov 2014 23:33:57 GMT: Finished Loading User 850 of 1000
Thu, 13 Nov 2014 23:33:59 GMT: Finished Loading User 860 of 1000
Thu, 13 Nov 2014 23:34:00 GMT: Finished Loading User 870 of 1000
Thu, 13 Nov 2014 23:34:02 GMT: Finished Loading User 880 of 1000
Thu, 13 Nov 2014 23:34:04 GMT: Finished Loading User 890 of 1000
Thu, 13 Nov 2014 23:34:06 GMT: Finished Loading User 900 of 1000
Thu, 13 Nov 2014 23:34:07 GMT: Finished Loading User 910 of 1000
Thu, 13 Nov 2014 23:34:08 GMT: Finished Loading User 920 of 1000
Thu, 13 Nov 2014 23:34:10 GMT: Finished Loading User 930 of 1000
Thu, 13 Nov 2014 23:34:12 GMT: Finished Loading User 940 of 1000
Thu, 13 Nov 2014 23:34:13 GMT: Finished Loading User 950 of 1000
Thu, 13 Nov 2014 23:34:15 GMT: Finished Loading User 960 of 1000
Thu, 13 Nov 2014 23:34:16 GMT: Finished Loading User 970 of 1000
Thu, 13 Nov 2014 23:34:17 GMT: Finished Loading User 980 of 1000
Thu, 13 Nov 2014 23:34:19 GMT: Finished Loading User 990 of 1000
Thu, 13 Nov 2014 23:34:21 GMT: Finished Loading 1000 Users
Thu, 13 Nov 2014 23:34:21 GMT: Finished Loading Follower 0 of 1000
Thu, 13 Nov 2014 23:34:23 GMT: Finished Loading Follower 10 of 1000
Thu, 13 Nov 2014 23:34:24 GMT: Finished Loading Follower 20 of 1000
Thu, 13 Nov 2014 23:34:26 GMT: Finished Loading Follower 30 of 1000
Thu, 13 Nov 2014 23:34:32 GMT: Finished Loading Follower 40 of 1000
Thu, 13 Nov 2014 23:34:36 GMT: Finished Loading Follower 50 of 1000
An error occurred executing a query
Warning: User u:tenant1:batch0-mariah-groner-216 failed to follow u:tenant1:batch0-hortensia-zia-98. Reason: An error occurred executing a query
An error occurred executing a query
Warning: User u:tenant1:batch0-renay-damiani-695 failed to follow u:tenant1:batch0-broderick-milward-78. Reason: An error occurred executing a query
An error occurred executing a query
Warning: User u:tenant1:batch0-renay-damiani-695 failed to follow u:tenant1:batch0-amos-kressierer-880. Reason: An error occurred executing a query
An error occurred executing a query
Warning: User u:tenant1:batch0-renay-damiani-695 failed to follow u:tenant1:batch0-charlott-lybert-803. Reason: An error occurred executing a query
An error occurred executing a query
Warning: User u:tenant1:batch0-renay-damiani-695 failed to follow u:tenant1:batch0-audra-billheimer-476. Reason: An error occurred executing a query
An error occurred executing a query
Warning: User u:tenant1:batch0-renay-damiani-695 failed to follow u:tenant1:batch0-sandi-hylinski-44. Reason: An error occurred executing a query
An error occurred executing a query
Warning: User u:tenant1:batch0-renay-damiani-695 failed to follow u:tenant1:batch0-amada-lopardo-842. Reason: An error occurred executing a query
You must be authenticated to follow a user
Warning: User u:tenant1:batch0-zachery-rezek-313 failed to follow u:tenant1:batch0-latasha-feilbach-258. Reason: You must be authenticated to follow a user
You must be authenticated to follow a user
Warning: User u:tenant1:batch0-zachery-rezek-313 failed to follow u:tenant1:batch0-clinton-wankel-757. Reason: You must be authenticated to follow a user
You must be authenticated to follow a user
Warning: User u:tenant1:batch0-zachery-rezek-313 failed to follow u:tenant1:batch0-charlott-lybert-803. Reason: You must be authenticated to follow a user
You must be authenticated to follow a user
Warning: User u:tenant1:batch0-zachery-rezek-313 failed to follow u:tenant1:batch0-debera-hapke-988. Reason: You must be authenticated to follow a user

Hilary Error:

[2014-11-13T23:46:00.271Z] WARN: oae-activity-buckets/12129 on roaming-217-62.host.udel.edu: Error collecting aggregate bucket (bucketNumber=0, type=activity)
err: {
"code": 500,
"msg": "An error occurred executing a query"
}
[2014-11-13T23:46:00.271Z] ERROR: oae-activity-buckets/12129 on roaming-217-62.host.udel.edu: Error collecting buckets
err: {
"code": 500,
"msg": "An error occurred executing a query"
}
[2014-11-13T23:46:01.662Z] ERROR: oae-cassandra/12129 on roaming-217-62.host.udel.edu: An error occurred executing a cassandra query
Error: Read Timed Out
at null._onTimeout (/Users/harrywang/sandbox/oae-dev/Hilary/node_modules/helenus/lib/connection.js:403:16)
at Timer.listOnTimeout as ontimeout
--
query: SELECT "followingId", "value" FROM "FollowingUsersFollowing" WHERE "userId" = ? AND "followingId" IN (?)
--
parameters: [
"u:tenant1:bJWU3g5wL",
[
"u:tenant1:Zk05ql5PL"
]
]

Cassandra Error:

WARN 18:34:21,770 Batch of prepared statements for [oae.ActivityStreams] is of size 106378, exceeding specified threshold of 5120 by 101258.

[nicolaasmatthijs]

Assigning to @simong for investigation

[simong]

Can you give some more details about your system/cluster? The only thing I can think of is that Cassandra doesn't have enough RAM/cpu available and some of the queries are timing out. If you're running everything on a single machine, it might be better to try and load smaller batches.

[harrywang]

@simong : MacBook Pro with Retina, 8G RAM. I tried to change user number to 100/200 using:
node generate.js -b 1 -t tenant1 -u 100 to generate -g 200 to generate -c 1000 -d 100

and got the following error:

Warning: Not sufficient users available to fill folder membership (batch0-consumptives-commotion-769 wanted 99 users)
Warning: Not sufficient users available to fill folder membership (batch0-elimination-484 wanted 107 users)

And changed to

node generate.js -b 1 -t tenant1 -u 1000 to generate -g 200 to generate -c 1000 -d 100

and ran into the same error after generating around 100 followers.

[nicolaasmatthijs]

@simong : Are these warnings errors or just warnings? In other words, will they prevent the generation of model loaders scripts?

[simong]

No, those are just warnings. It means a folder won't have as many members as the statistical model dictates. That's usually fine.

[nicolaasmatthijs]

@harrywang : if you ignore the warnings, are you able to successfully load the generated data into your instance?

[harrywang]

I justed tried with

node generate.js -b 1 -t tenant1 -u 1000 to generate -g 200 to generate -c 1000 -d 100
node loaddata.js -b -h http://tenant1.oae.com

There are lots of errors from loader, cassandra, and hilary. I had to restart the Mac and OAE and found that only some users (214) and contents (only 11) were created, nothing else.

Loader log: https://gist.github.com/harrywang/fc93b7f86bd9f9673af0
Cassandra log: https://gist.github.com/harrywang/ba9bbf20291bb07716ee
Hilary log: https://gist.github.com/harrywang/364b43cc183ae6132a7b

Screenshot after reboot:

[nicolaasmatthijs]

Assigning to @simong for further investigation

[simong]

Thank you for the logs, they certainly help.

A couple of things.

1. Can you double-check that you can manually create a collaborative document? Those connect ECONNREFUSED warnings make me thing that either your etherpad server is misconfigured or it's simply not running.
2. Those WARN 13:29:28,727 Batch of prepared statements for [oae.ActivityStreams] in the Cassandra logs are fairly harmless. These are triggered because the ActivityStreams are denormalized and are in some cases very big.
3. Those An error occurred executing a query in your loader log should correspond to an error log in your Hilary log. Any chance you could provide those?

[harrywang]

@simong sorry for the late reply - I actually do not have eitherpad and previewer configured locally - I forgot to mention that. Where is the Hilary log?