Export does not work with Schooltool/Ubuntu installed on VirtualBox

Asked by Thomas Büsser on 2017-01-05

I have the problem, that the export does not work with Schooltool/Ubuntu installed on VirtualBox.
Everything else works perfectly fine.
When I start an export there is only the message:
---
"Scheduled.

You can close this dialogue and download the exported data later from your home page."
---

But no link is produced and in my message-center I got only these messages:
---
Message Group Received
Generating Thomas Büsser detail report...

2017-01-04 23:43
Generating school export...

2017-01-04 21:26
Generating school export...

---

Thanks for your help!

Question information

Language:
English Edit question
Status:
Open
For:
SchoolTool Edit question
Assignee:
No assignee Edit question
Last query:
2017-01-06
Last reply:
Thomas Büsser (thomasbuesser) said : #1

Here are some more informations:

I restartet the schooltool service several times.

I work with 14.04 LTS

The logs:
--
error.log:

2017-01-02 19:35:41,581 ['/var/run/schooltool/zeo.sock'] ClientStorage (pid=1241) created RW/normal for storage: '1'
2017-01-02 19:35:41,584 created temporary cache file '<fdopen>'
2017-01-02 19:35:41,589 ['/var/run/schooltool/zeo.sock'] Testing connection <ManagedClientConnection /var/run/schooltool/zeo.sock>
2017-01-02 19:35:41,591 (/var/run/schooltool/zeo.sock) received handshake 'Z3101'
2017-01-02 19:35:41,692 ['/var/run/schooltool/zeo.sock'] Server authentication protocol None
2017-01-02 19:35:41,693 ['/var/run/schooltool/zeo.sock'] Connected to storage: /var/run/schooltool/zeo.sock
2017-01-02 19:35:41,694 ['/var/run/schooltool/zeo.sock'] No verification necessary -- empty cache
2017-01-02 19:35:41,706 main db: evolving in mode EVOLVEMINIMUM
2017-01-02 21:30:11,664 ['/var/run/schooltool/zeo.sock'] ClientStorage (pid=2386) created RW/normal for storage: '1'
2017-01-02 21:30:11,666 created temporary cache file '<fdopen>'
2017-01-02 21:30:11,675 ['/var/run/schooltool/zeo.sock'] Testing connection <ManagedClientConnection /var/run/schooltool/zeo.sock>
2017-01-02 21:30:11,676 (/var/run/schooltool/zeo.sock) received handshake 'Z3101'
2017-01-02 21:30:11,779 ['/var/run/schooltool/zeo.sock'] Server authentication protocol None
2017-01-02 21:30:11,781 ['/var/run/schooltool/zeo.sock'] Connected to storage: /var/run/schooltool/zeo.sock
2017-01-02 21:30:11,783 ['/var/run/schooltool/zeo.sock'] No verification necessary -- empty cache
2017-01-02 21:30:11,801 main db: evolving in mode EVOLVEMINIMUM
2017-01-04 16:07:02,427 ['/var/run/schooltool/zeo.sock'] ClientStorage (pid=3737) created RW/normal for storage: '1'
2017-01-04 16:07:02,428 created temporary cache file '<fdopen>'
2017-01-04 16:07:02,446 ['/var/run/schooltool/zeo.sock'] Testing connection <ManagedClientConnection /var/run/schooltool/zeo.sock>
2017-01-04 16:07:02,447 (/var/run/schooltool/zeo.sock) received handshake 'Z3101'
2017-01-04 16:07:02,547 ['/var/run/schooltool/zeo.sock'] Server authentication protocol None
2017-01-04 16:07:02,549 ['/var/run/schooltool/zeo.sock'] Connected to storage: /var/run/schooltool/zeo.sock
2017-01-04 16:07:02,551 ['/var/run/schooltool/zeo.sock'] No verification necessary -- empty cache
2017-01-04 16:07:02,612 main db: evolving in mode EVOLVEMINIMUM
2017-01-04 16:29:19,927 ['/var/run/schooltool/zeo.sock'] ClientStorage (pid=1246) created RW/normal for storage: '1'
2017-01-04 16:29:19,932 created temporary cache file '<fdopen>'
2017-01-04 16:29:19,947 ['/var/run/schooltool/zeo.sock'] Testing connection <ManagedClientConnection /var/run/schooltool/zeo.sock>
2017-01-04 16:29:19,947 (/var/run/schooltool/zeo.sock) received handshake 'Z3101'
2017-01-04 16:29:20,051 ['/var/run/schooltool/zeo.sock'] Server authentication protocol None
2017-01-04 16:29:20,053 ['/var/run/schooltool/zeo.sock'] Connected to storage: /var/run/schooltool/zeo.sock
2017-01-04 16:29:20,056 ['/var/run/schooltool/zeo.sock'] No verification necessary -- empty cache
2017-01-04 16:29:20,117 main db: evolving in mode EVOLVEMINIMUM
2017-01-04 19:23:12,373 ['/var/run/schooltool/zeo.sock'] ClientStorage (pid=1237) created RW/normal for storage: '1'
2017-01-04 19:23:12,376 created temporary cache file '<fdopen>'
2017-01-04 19:23:12,383 ['/var/run/schooltool/zeo.sock'] Testing connection <ManagedClientConnection /var/run/schooltool/zeo.sock>
2017-01-04 19:23:12,384 (/var/run/schooltool/zeo.sock) received handshake 'Z3101'
2017-01-04 19:47:00,134 ['/var/run/schooltool/zeo.sock'] Server authentication protocol None
2017-01-04 19:47:00,135 ['/var/run/schooltool/zeo.sock'] Connected to storage: /var/run/schooltool/zeo.sock
2017-01-04 19:47:00,146 ['/var/run/schooltool/zeo.sock'] No verification necessary -- empty cache
2017-01-04 19:47:00,200 main db: evolving in mode EVOLVEMINIMUM
---

celery_report

[2017-01-02 21:29:46,245: WARNING/Worker-1] (1944) CW: error connecting to /var/run/schooltool/zeo.sock: ECONNREFUSED
("\nThe 'celeryd' command is deprecated, please use 'celery worker' instead:\n\n$ celery worker --loader=schooltool.task.celery:ReportLoader --config=schooltool.task.con$

 -------------- celery@thomas-VirtualBox v3.1.6 (Cipater)
---- **** -----
--- * *** * -- Linux-4.4.0-31-generic-i686-with-Ubuntu-14.04-trusty
-- * - **** ---
- ** ---------- [config]
- ** ---------- .> broker: redis://127.0.0.1:7079/0
- ** ---------- .> app: default:0xb6e0420c (schooltool.task.celery.ReportLoader)
- ** ---------- .> concurrency: 1 (prefork)
- *** --- * --- .> events: OFF (enable -E to monitor this worker)
-- ******* ----
--- ***** ----- [queues]
 -------------- .> default exchange=default(direct) key=default
                .> zodb.report exchange=zodb.report(direct) key=zodb.report

[2017-01-02 21:29:58,155: WARNING/MainProcess] celery@thomas-VirtualBox ready.

[2017-01-04 16:06:43,972: WARNING/MainProcess] celery@thomas-VirtualBox ready.

worker: Cold shutdown (MainProcess)
[2017-01-04 16:27:24,475: WARNING/Worker-1] (3753) CW: error connecting to /var/run/schooltool/zeo.sock: ECONNREFUSED

worker: Warm shutdown (MainProcess)
("\nThe 'celeryd' command is deprecated, please use 'celery worker' instead:\n\n$ celery worker --loader=schooltool.task.celery:ReportLoader --config=schooltool.task.con$

 -------------- celery@thomas-VirtualBox v3.1.6 (Cipater)
---- **** -----
--- * *** * -- Linux-4.4.0-31-generic-i686-with-Ubuntu-14.04-trusty
-- * - **** ---
- ** ---------- [config]
- ** ---------- .> broker: redis://127.0.0.1:7079/0
- ** ---------- .> app: default:0xb6c2430c (schooltool.task.celery.ReportLoader)
- ** ---------- .> concurrency: 1 (prefork)
- *** --- * --- .> events: OFF (enable -E to monitor this worker)
-- ******* ----
--- ***** ----- [queues]
 -------------- .> default exchange=default(direct) key=default
                .> zodb.report exchange=zodb.report(direct) key=zodb.report

[2017-01-04 16:28:50,583: WARNING/MainProcess] celery@thomas-VirtualBox ready.

worker: Cold shutdown (MainProcess)
[2017-01-04 19:20:54,231: WARNING/Worker-1] (2006) CW: error connecting to /var/run/schooltool/zeo.sock: ECONNREFUSED

worker: Warm shutdown (MainProcess)
("\nThe 'celeryd' command is deprecated, please use 'celery worker' instead:\n\n$ celery worker --loader=schooltool.task.celery:ReportLoader --config=schooltool.task.con$

 -------------- celery@thomas-VirtualBox v3.1.6 (Cipater)
---- **** -----
--- * *** * -- Linux-4.4.0-31-generic-i686-with-Ubuntu-14.04-trusty
-- * - **** ---

- ** ---------- [config]
- ** ---------- .> broker: redis://127.0.0.1:7079/0
- ** ---------- .> app: default:0xb6e1620c (schooltool.task.celery.ReportLoader)
- ** ---------- .> concurrency: 1 (prefork)
- *** --- * --- .> events: OFF (enable -E to monitor this worker)
-- ******* ----
--- ***** ----- [queues]
 -------------- .> default exchange=default(direct) key=default
                .> zodb.report exchange=zodb.report(direct) key=zodb.report

[2017-01-04 19:22:52,824: WARNING/MainProcess] celery@thomas-VirtualBox ready.

worker: Cold shutdown (MainProcess)
[2017-01-04 19:36:03,049: WARNING/Worker-1] (2014) CW: error connecting to /var/run/schooltool/zeo.sock: ECONNREFUSED
("\nThe 'celeryd' command is deprecated, please use 'celery worker' instead:\n\n$ celery worker --loader=schooltool.task.celery:ReportLoader --config=schooltool.task.con$

 -------------- celery@thomas-VirtualBox v3.1.6 (Cipater)
---- **** -----
--- * *** * -- Linux-4.4.0-31-generic-i686-with-Ubuntu-14.04-trusty
-- * - **** ---
- ** ---------- [config]
- ** ---------- .> broker: redis://127.0.0.1:7079/0
- ** ---------- .> app: default:0xb6e7a20c (schooltool.task.celery.ReportLoader)
- ** ---------- .> concurrency: 1 (prefork)
- *** --- * --- .> events: OFF (enable -E to monitor this worker)
-- ******* ----
--- ***** ----- [queues]
 -------------- .> default exchange=default(direct) key=default
                .> zodb.report exchange=zodb.report(direct) key=zodb.report

[2017-01-04 19:46:42,859: WARNING/MainProcess] celery@thomas-VirtualBox ready.

---
supervisord.log

2017-01-04 16:06:28,021 INFO waiting for redis, zeo, celery_report, schooltool to die
2017-01-04 16:06:28,073 WARN received SIGTERM indicating exit request
2017-01-04 16:06:28,850 INFO stopped: schooltool (terminated by SIGQUIT (core dumped))
2017-01-04 16:06:29,462 INFO stopped: zeo (terminated by SIGQUIT (core dumped))
2017-01-04 16:06:29,499 INFO stopped: redis (terminated by SIGQUIT (core dumped))
2017-01-04 16:06:31,143 INFO waiting for celery_report to die
2017-01-04 16:06:33,624 INFO stopped: celery_report (exit status 0)
2017-01-04 16:06:36,002 CRIT Set uid to user 117
2017-01-04 16:06:36,041 INFO RPC interface 'supervisor' initialized
2017-01-04 16:06:36,041 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2017-01-04 16:06:36,047 INFO daemonizing the supervisord process
2017-01-04 16:06:36,054 INFO supervisord started with pid 3729
2017-01-04 16:06:37,068 INFO spawned: 'redis' with pid 3732
2017-01-04 16:06:37,103 INFO spawned: 'zeo' with pid 3733
2017-01-04 16:06:37,170 INFO spawned: 'celery_report' with pid 3734
2017-01-04 16:06:37,209 INFO spawned: 'schooltool' with pid 3737
2017-01-04 16:06:38,241 INFO success: redis entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2017-01-04 16:06:38,241 INFO success: zeo entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-01-04 16:06:38,241 INFO success: celery_report entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-01-04 16:06:43,058 INFO success: schooltool entered RUNNING state, process has stayed up for > than 5 seconds (startsecs)
2017-01-04 16:27:24,408 INFO waiting for redis, zeo, celery_report, schooltool to die
2017-01-04 16:27:24,438 WARN received SIGTERM indicating exit request
2017-01-04 16:27:24,441 INFO stopped: schooltool (terminated by SIGQUIT)
2017-01-04 16:27:24,463 INFO stopped: redis (terminated by SIGQUIT)
2017-01-04 16:27:24,474 INFO stopped: zeo (terminated by SIGQUIT)
2017-01-04 16:27:25,185 WARN received SIGTERM indicating exit request
2017-01-04 16:27:25,734 INFO stopped: celery_report (exit status 0)
2017-01-04 16:28:26,634 CRIT Set uid to user 117
2017-01-04 16:28:26,693 INFO RPC interface 'supervisor' initialized
2017-01-04 16:28:26,694 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2017-01-04 16:28:26,701 INFO daemonizing the supervisord process
2017-01-04 16:28:26,709 INFO supervisord started with pid 1181
2017-01-04 16:28:26,782 INFO spawned: 'redis' with pid 1241
2017-01-04 16:28:26,850 INFO spawned: 'zeo' with pid 1244
2017-01-04 16:28:26,901 INFO spawned: 'celery_report' with pid 1245
2017-01-04 16:28:27,004 INFO spawned: 'schooltool' with pid 1246
2017-01-04 16:28:28,074 INFO success: redis entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2017-01-04 16:28:28,074 INFO success: zeo entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-01-04 16:28:28,074 INFO success: celery_report entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-01-04 16:28:32,142 INFO success: schooltool entered RUNNING state, process has stayed up for > than 5 seconds (startsecs)
2017-01-04 19:20:54,029 INFO waiting for redis, zeo, celery_report, schooltool to die
2017-01-04 19:20:54,073 INFO stopped: schooltool (terminated by SIGQUIT)
2017-01-04 19:20:54,074 WARN received SIGTERM indicating exit request
2017-01-04 19:20:54,113 INFO stopped: redis (terminated by SIGQUIT)
2017-01-04 19:20:54,113 INFO stopped: zeo (terminated by SIGQUIT)
2017-01-04 19:20:54,911 WARN received SIGTERM indicating exit request
2017-01-04 19:20:57,118 INFO stopped: celery_report (exit status 0)
2017-01-04 19:22:24,191 CRIT Set uid to user 117
2017-01-04 19:22:24,262 INFO RPC interface 'supervisor' initialized
2017-01-04 19:22:24,262 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2017-01-04 19:22:24,278 INFO daemonizing the supervisord process
2017-01-04 19:22:24,282 INFO supervisord started with pid 1180
2017-01-04 19:22:25,306 INFO spawned: 'redis' with pid 1221
2017-01-04 19:22:25,368 INFO spawned: 'zeo' with pid 1224

2017-01-04 19:22:25,469 INFO spawned: 'celery_report' with pid 1229
2017-01-04 19:22:25,603 INFO spawned: 'schooltool' with pid 1237
2017-01-04 19:22:26,663 INFO success: redis entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2017-01-04 19:22:26,663 INFO success: zeo entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-01-04 19:22:26,663 INFO success: celery_report entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-01-04 19:22:30,723 INFO success: schooltool entered RUNNING state, process has stayed up for > than 5 seconds (startsecs)
2017-01-04 19:36:01,364 INFO waiting for redis, zeo, celery_report, schooltool to die
2017-01-04 19:36:01,405 WARN received SIGTERM indicating exit request
2017-01-04 19:36:02,107 INFO stopped: schooltool (terminated by SIGQUIT (core dumped))
2017-01-04 19:36:02,875 INFO stopped: redis (terminated by SIGQUIT (core dumped))
2017-01-04 19:36:03,049 INFO stopped: zeo (terminated by SIGQUIT (core dumped))
2017-01-04 19:36:04,405 INFO waiting for celery_report to die
2017-01-04 19:36:04,813 INFO stopped: celery_report (exit status 0)
2017-01-04 19:46:33,135 CRIT Set uid to user 117
2017-01-04 19:46:33,172 INFO RPC interface 'supervisor' initialized
2017-01-04 19:46:33,173 CRIT Server 'unix_http_server' running without any HTTP authentication checking
2017-01-04 19:46:33,181 INFO daemonizing the supervisord process
2017-01-04 19:46:33,187 INFO supervisord started with pid 3490
2017-01-04 19:46:34,223 INFO spawned: 'redis' with pid 3493
2017-01-04 19:46:34,261 INFO spawned: 'zeo' with pid 3494
2017-01-04 19:46:34,316 INFO spawned: 'celery_report' with pid 3495
2017-01-04 19:46:34,344 INFO spawned: 'schooltool' with pid 3496
2017-01-04 19:46:35,372 INFO success: redis entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2017-01-04 19:46:35,372 INFO success: zeo entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-01-04 19:46:35,372 INFO success: celery_report entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)
2017-01-04 19:46:39,391 INFO success: schooltool entered RUNNING state, process has stayed up for > than 5 seconds (startsecs)

--

zeo.log

2017-01-04T16:06:38 INFO ZEO.runzeo (3733) opening storage '1' using FileStorage
------
2017-01-04T16:06:38 INFO ZEO.StorageServer StorageServer created RW with storages: 1:RW:/var/lib/schooltool/Data.fs
------
2017-01-04T16:06:38 INFO ZEO.zrpc (3733) listening on /var/run/schooltool/zeo.sock
------
2017-01-04T16:07:02 INFO ZEO.StorageServer new connection : <ManagedServerConnection >
------
2017-01-04T16:07:02 INFO ZEO.StorageServer new connection : <ManagedServerConnection >
------
2017-01-04T16:07:02 INFO ZEO.zrpc.Connection(S) () received handshake 'Z3101'
------
2017-01-04T16:07:02 INFO ZEO.StorageServer new connection : <ManagedServerConnection >
------
2017-01-04T16:07:02 INFO ZEO.zrpc.Connection(S) () received handshake 'Z3101'
------
2017-01-04T16:27:24 INFO ZEO.StorageServer disconnected
------
2017-01-04T16:28:29 INFO ZEO.runzeo (1244) opening storage '1' using FileStorage
------
2017-01-04T16:28:30 INFO ZEO.StorageServer StorageServer created RW with storages: 1:RW:/var/lib/schooltool/Data.fs
------
2017-01-04T16:28:30 INFO ZEO.zrpc (1244) listening on /var/run/schooltool/zeo.sock
------
2017-01-04T16:29:19 INFO ZEO.zrpc.Connection(S) () received handshake 'Z3101'
------
2017-01-04T16:29:19 INFO ZEO.StorageServer new connection : <ManagedServerConnection >
------
2017-01-04T16:29:19 INFO ZEO.zrpc.Connection(S) () received handshake 'Z3101'
------
2017-01-04T19:20:54 INFO ZEO.StorageServer disconnected
------
2017-01-04T19:22:28 INFO ZEO.runzeo (1224) opening storage '1' using FileStorage
------
2017-01-04T19:22:29 INFO ZEO.StorageServer StorageServer created RW with storages: 1:RW:/var/lib/schooltool/Data.fs
------
2017-01-04T19:22:29 INFO ZEO.zrpc (1224) listening on /var/run/schooltool/zeo.sock
------
2017-01-04T19:23:11 INFO ZEO.StorageServer new connection : <ManagedServerConnection >
------
2017-01-04T19:23:12 INFO ZEO.zrpc.Connection(S) () received handshake 'Z3101'
------
2017-01-04T19:36:02 INFO ZEO.StorageServer disconnected
------
2017-01-04T19:46:35 INFO ZEO.runzeo (3494) opening storage '1' using FileStorage
------
2017-01-04T19:46:36 INFO ZEO.StorageServer StorageServer created RW with storages: 1:RW:/var/lib/schooltool/Data.fs
------
2017-01-04T19:46:36 INFO ZEO.zrpc (3494) listening on /var/run/schooltool/zeo.sock
------
2017-01-04T19:46:59 INFO ZEO.StorageServer new connection : <ManagedServerConnection >
------
2017-01-04T19:46:59 INFO ZEO.zrpc.Connection(S) () received handshake 'Z3101'
------
2017-01-04T19:47:00 INFO ZEO.StorageServer new connection : <ManagedServerConnection >
------
2017-01-04T19:47:00 INFO ZEO.zrpc.Connection(S) () received handshake 'Z3101'
------
2017-01-04T19:49:22 INFO ZEO.StorageServer pack(time=1483555762.695744) started...
------
2017-01-04T19:49:22 INFO ZEO.StorageServer pack(time=1483555762.695744) complete

Thomas Büsser (thomasbuesser) said : #2

And even more info:

I copied the Data.fs to an NON-VM-Ubuntu and SchoolTool-Installation --> Everything and especialy the export work perfectly.

I only had to ajust the permission-settings of Data.fs.

Is this a good way to export Schooltool-data?

Thanks a lot for all your advices.

Douglas Cerna (replaceafill) said : #3

Hi Thomas.

Regarding the VirtualBox problem, I have seen similar issues with the exports/reports not being produced when the VM or server doesn't have enough RAM. That's probably why it's now working on your NON-VM server. Just an idea ofc. And when you move the database from one server to another it's also a good idea to move the /var/lib/schooltool/blobs directory too (http://book.schooltool.org/database.html).

Thomas Büsser (thomasbuesser) said : #4

Dear Douglas

Thank you for your response. As I was searching for an answer to my problem, I found the hint about the RAM before. I switched to 2048 MB and now to 4096.
But it did not work - sadly.
Thanks too for the adwise about the blobs directory.

Can you help with this problem?

Provide an answer of your own, or ask Thomas Büsser for more information if necessary.

To post a message you must log in.