Can't get import to work

I applied the workaround [eliminating the duplicate "service" command in the last line] and the system seemed to slow to a crawl. top output extract:

  PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
  543 redis     20   0   38528   1076    724 S  0.3  0.1   0:11.11 redis-server
 6997 canvas    20   0  624360 159804    344 D  0.3 12.5   0:16.64 ruby
 7138 canvas    20   0  674976 355472    372 D  0.3 27.7   0:14.28 ruby
 7182 canvas    20   0  692448 225800   2196 D  0.3 17.6   0:03.07 ruby

A root web request produced this output:

An internal error occurred while trying to spawn the application. Exception type: Passenger::TimeoutException Error message: Read timeout Backtrace: in 'void Passenger::SpawningKit::SmartSpawner::sendSpawnCommand(Passenger::SpawningKit::Spawner::NegotiationDetails&)' (SmartSpawner.h:657) in 'Passenger::SpawningKit::Spawner::NegotiationDetails Passenger::SpawningKit::SmartSpawner::sendSpawnCommandAndGetNegotiationDetails(const Options&)' (SmartSpawner.h:618) in 'virtual Passenger::SpawningKit::Result Passenger::SpawningKit::SmartSpawner::spawn(const Options&)' (SmartSpawner.h:781) in 'void Passenger::ApplicationPool2::Group::spawnThreadRealMain(const SpawnerPtr&, const Passenger::ApplicationPool2::Options&, unsigned int)' (SpawningAndRestarting.cpp:94)

Perhaps some of the other changes I made affected this? I could start fresh and apply the fix.

Here's a log extract from error.log:

[ 2015-11-24 22:57:29.3845 6877/7fe78f7cc700 age/Ust/UstRouterMain.cpp:337 ]: Signal received. Gracefully shutting down... (send signal 2 more time(s) to force shutdown)
[ 2015-11-24 22:57:29.3846 6877/7fe7950b4780 age/Ust/UstRouterMain.cpp:399 ]: Received command to shutdown gracefully. Waiting until all clients have disconnected...
[ 2015-11-24 22:57:29.3846 6877/7fe78f7cc700 Ser/Server.h:752 ]: [LoggerApiServer] Freed 0 spare client objects
[ 2015-11-24 22:57:29.3846 6877/7fe78f7cc700 Ser/Server.h:443 ]: [LoggerApiServer] Shutdown finished
[ 2015-11-24 22:57:29.3848 6877/7fe7950b4780 age/Ust/UstRouterMain.cpp:424 ]: Passenger UstRouter shutdown finished
[ 2015-11-24 22:57:29.3607 6870/7fa21b7fe700 Ser/Server.h:752 ]: [ServerThr.1] Freed 128 spare client objects
[ 2015-11-24 22:57:29.3849 6870/7fa21b7fe700 Ser/Server.h:443 ]: [ServerThr.1] Shutdown finished
[ 2015-11-24 22:57:29.4225 6870/7fa2252ff780 age/Cor/CoreMain.cpp:942 ]: Passenger core shutdown finished
[ 2015-11-24 22:57:29.9233 6896/7f1548139780 age/Wat/WatchdogMain.cpp:1274 ]: Starting Passenger watchdog...
[ 2015-11-24 22:57:29.9293 6899/7f6044ac8780 age/Cor/CoreMain.cpp:957 ]: Starting Passenger core...
[ 2015-11-24 22:57:29.9294 6899/7f6044ac8780 age/Cor/CoreMain.cpp:234 ]: Passenger core running in multi-application mode.
[ 2015-11-24 22:57:29.9302 6899/7f6044ac8780 age/Cor/CoreMain.cpp:707 ]: Passenger core online, PID 6899
[ 2015-11-24 22:57:29.9375 6904/7fcc25caf780 age/Ust/UstRouterMain.cpp:430 ]: Starting Passenger UstRouter...
[ 2015-11-24 22:57:29.9378 6904/7fcc25caf780 age/Ust/UstRouterMain.cpp:311 ]: Passenger UstRouter online, PID 6904
[Tue Nov 24 22:57:29.939000 2015] [mpm_event:notice] [pid 6893:tid 140247796737920] AH00489: Apache/2.4.10 (Debian) Phusion_Passenger/5.0.17 OpenSSL/1.0.1k configured -- resuming normal operations
[Tue Nov 24 22:57:29.939187 2015] [core:notice] [pid 6893:tid 140247796737920] AH00094: Command line: '/usr/sbin/apache2'
[ 2015-11-24 22:57:34.5414 6821/7f1f08081780 age/Wat/WatchdogMain.cpp:453 ]: Some Phusion Passenger agent processes did not exit in time, forcefully shutting down all.
App 6997 stdout:
App 7028 stdout:
App 7037 stdout:
App 7045 stdout:
[ 2015-11-24 22:59:56.0826 6899/7f603effe700 age/Cor/Req/Utils.cpp:95 ]: [Client 1-3] Sending 502 response: application did not send a complete response
[ 2015-11-24 22:59:56.8418 6899/7f603effe700 age/Cor/CoreMain.cpp:794 ]: Disconnecting long-running connections for process 7028, application /var/www/canvas
[ 2015-11-24 22:59:57.0621 6899/7f603effe700 age/Cor/Req/Utils.cpp:95 ]: [Client 1-4] Sending 502 response: application did not send a complete response
[ 2015-11-24 22:59:57.0621 6899/7f6044aa5700 App/Poo/AnalyticsCollection.cpp:104 ]: Process (pid=7037, group=/var/www/canvas) no longer exists! Detaching it from the pool.
[ 2015-11-24 22:59:57.1875 6899/7f6044aa5700 age/Cor/CoreMain.cpp:794 ]: Disconnecting long-running connections for process 7037, application /var/www/canvas
[ 2015-11-24 23:06:56.7806 6899/7f603effe700 age/Cor/Req/CheckoutSession.cpp:274 ]: [Client 1-6] Cannot checkout session (exception type Passenger::TimeoutException): Read timeout
[ 2015-11-24 23:06:58.3356 6899/7f603effe700 age/Cor/Req/CheckoutSession.cpp:274 ]: [Client 1-7] Cannot checkout session (exception type Passenger::TimeoutException): Read timeout
root@canvas log/apache2# tail -100  error.log
[ 2015-11-24 20:37:34.1777 719/7f3dc511a780 age/Ust/UstRouterMain.cpp:399 ]: Received command to shutdown gracefully. Waiting until all clients have disconnected...
[ 2015-11-24 20:37:34.1777 719/7f3dbf832700 Ser/Server.h:752 ]: [LoggerApiServer] Freed 0 spare client objects
[ 2015-11-24 20:37:34.1777 719/7f3dbf832700 Ser/Server.h:443 ]: [LoggerApiServer] Shutdown finished
[ 2015-11-24 20:37:34.1778 719/7f3dc511a780 age/Ust/UstRouterMain.cpp:424 ]: Passenger UstRouter shutdown finished

Please implement the workaround and see if that resolves your issues?

FWIW we plan to include this fix in the v14.1 appliance.

Although it may be a bit of a pain I would encourage you to create a new VM, apply the required changes (to fix the bug) and then test the import and fingers crossed it will work.

PS thanks for catching the typo. I've fixed it now. :)

It's no great surprise that password authentication failed as we used the "--disabled-password" switch when we created the account. But a bit of googling and looking through the canvas build code; I think that I have inadvertantly introduced a new issue with the workaround/fix for the delayed jobs runner. The TurnKey appliances uses "canvas" as the DB user as well as the Linux user. That wouldn't usually pose an issue when used with a MySQL DB (where all my experience is and what most of the TurnKey apps use as a backend DB); but IIRC when using PostgreSQL it actually uses a Linux user as the DB user. I don't know for sure but I think that may be causing Canvas some confusion.

I'll install Canvas and have a bit of a play with it and get back to you ASAP...

Regardless to test, I created a new Canvas instance and used the "old" instructions (i.e. created a new "canvas" Linux user) but have been unable to reproduce your Apache errors for some reason. In fact I have no "stderr" entries in my /var/log/apache2/error.log at all...

However while trying to reproduce those errors, I did discover that I couldn't upload any files! To resolve that I just changed the permissions on the /tmp/attachment_fu directory like this:

chmod -R 775 /tmp/attachment_fu

Initially I was a little concerned about that fix sticking over time (/tmp is usually cleared on reboot) but it looks like on reboot that it recreates /tmp/attachment_fu and makes 'canvas' the owner (so that's all good).

So TBH I'm not quite sure what is going on... I am inclined to suggest that you adjust the permissions on /tmp/attachment_fu as I did and try uploading one more time. If that still doesn't work, then I know it's a pain; but perhaps start again and add the "canvasuser" account this time (as the instruction now suggest). Remember that you'll also need to readjust the /tmp/attachment_fu permissions (or reboot).

Also, FWIW beyond the Apache error log there are specific Canvas logs. They can be found in /var/www/canvas/logs (that's how I discovered the

I started fresh and after the system came up, but before even logging into Canas the first time, applied the workaround.

After logging in, I attempted to import content from a small course on my production system into a new course I created.

Under "Current Jobs" it showed "Canvas Common Cartridge" as "Pending" for maybe 20 minutes then it finally changed to "Failed" with this explanation:

"The file upload process timed out."

The full system log is here: http://www.pastebucket.com/97307

Thanks for the prompt replies Jeremy!

James

Nice detective work -- you got it Jeremy!

I rebuilt from scratch, applied the updated workaround, then changed permissions on /tmp/attachment_fu.

The import now works. There were some missing images that I need to investigate but my instinct is that is my own issue.

Thanks.

So, it was not my problem:

I took a course from my production system and exported it. When I re-imported it into a new course on prodcution, the Files section was populated correctly. Using the same export file, the TKL import succeeded. However, while the Files section appeared to be identical as production, including folders, file names, and file sizes, the images were not displayed, nor could they be downloaded.

I looked around and found the correct images here: /var/www/canvas/tmp/files/0000/0024 but they didn't seem to make their way into the actual file location. There were no obvious apache errors. I didn't see anything suspious in the Canvas production log

You can download the production.log file here (target download page has an ad…):

[DELETED]

This feels like another permissions issue.

I just built a test course and added no content except a 24k image in the Files section. Similar to the above, the file information is accurate but the thumbnail does not appear and the file will not download. So, the issue might be images in general, not import.

I took a closer look at the production.log and saw this:

[- 0b3d520e-f60c-43c0-a555-60bbe6909072] Started GET "/courses/2/files/46/preview" for 128.143.104.233 at 2016-01-06 20:41:40 +0000
<snip>
[- 0b3d520e-f60c-43c0-a555-60bbe6909072] Redirected to https://www.example.com/courses/2/files/46/course%20files/JR-BOB-DOBBS.jpg?download_frd=1&sf_verifier=92717feb6e5fb0cf776d12182b41c631&ts=1452112900&user_id=1

In answer to the 'what domain is being served' question I had just used www.example.com because my use was only going to be by IP. However, seeing it in the log got my attention.

So, I re-built the entire machine, applying the workaround. This time I just used my own fake domain, www.canvaslocal.com, and added an entry in my local hosts file.

When it came up, I re-imported the original production canvas export and all the content, including the images was present.

All good on my end then. Thanks again.