search

maths / moodle-qtype_stack

Stack question type for Moodle
GNU General Public License v3.0
142 stars 149 forks source link

CAS timed out from Moodle, but works from CMDline #513

Closed vahem2lu closed 7 months ago

vahem2lu commented 5 years ago

Hi

I'm having a problem with PHP7.3 and Apache 2.4 and Moodle 3.7.1 (Build: 20190708) where maxima and gnuplot seems to working from command line, but images are not displayed in Moodle and error says that CAS timed out.

Using Arch Linux and Maxima 5.43.0 and gnuplot 5.2 patchlevel 7 from Arch repository.

When doing save for stack question type and when using stack debugger (healthcheck)

Context used
Platform: unix-optimised
Maxima shell command: /my/moodle/moodledata/stack/maxima_opt_auto
Maxima initial command: load("/my/moodle/moodledata/stack/maximalocal.mac");

Maxima timeout: 10
Maxima command
cab:block([RANDOM_SEED, ans1], stack_randseed(1), make_multsgn("dot"), make_complexJ("i"), make_arccos("cos-1"), OPT_NoFloats:true, sqrtdispflag:true, simp:true, assume_pos:false, assume_real:false, lmxchar:"[", print("[STACKSTART Locals= [ ") , print("-1=[ error= ["), cte("__stackmaximaversion",errcatch(__stackmaximaversion:stackmaximaversion)) , print("0=[ error= ["), cte("ans1",errcatch(ans1:plot(x^2,[x,-1,1],[y,0,2]))) , print("] ]"), return(true) ); 
Unpacked result as
Array
(
    [-1] => Array
        (
            [key] => __stackmaximaversion
            [value] => 2019090200
            [dispvalue] => 2019090200
            [display] => 2019090200
            [error] => 
        )

    [0] => Array
        (
            [error] => The CAS timed out.
        )

)

SVG images are being created to moodledata/stack/plots directory.

It doesn't matter if I'm using optimized maxima image or system one. Only difference is creation time (optimised is faster, like docs say). :)

Apache's logs doesn't say anything, Google DevTools Debugger doesn't show anything what can be considered as error and/or warning and/or missing (JS or anything), and stack logs directory in moodledata/stack/logs is totally empty.

When I'm using the same command from commandline, everything works:

# /my/moodle/moodledata/stack/maxima_opt_auto
Maxima restarted.
(%i2) load("/my/moodle/moodledata/stack/maximalocal.mac");

[ STACK-Maxima started, library version 2019090200 ]
(%o2) "/my/moodle/moodledata/stack/maximalocal.mac"
(%i3) cab:block([RANDOM_SEED, ans1], stack_randseed(1), make_multsgn("dot"), make_complexJ("i"), make_arccos("cos-1"), OPT_NoFloats:true, sqrtdispflag:true, simp:true, assume_pos:false, assume_real:false, lmxchar:"[", print("[STACKSTART Locals= [ ") , print("-1=[ error= ["), cte("__stackmaximaversion",errcatch(__stackmaximaversion:stackmaximaversion)) , print("0=[ error= ["), cte("ans1",errcatch(ans1:plot(x^2,[x,-1,1],[y,0,2]))) , print("] ]"), return(true) );

[STACKSTART Locals= [
-1=[ error= [
], key = [
__stackmaximaversion
]
, value = [
2019090200
], dispvalue = [
2019090200
], display = [
2019090200
]
],
0=[ error= [
], key = [
ans1
]
, value = [
" <html><div class='stack_plot'><img src='!ploturl!stackplot-3782018093-91095845.svg' alt='STACK auto-generated plot of x^2 with parameters [[x,-1,1],[y,0,2]]' width='450' /></div></html> "
], dispvalue = [
" <html><div class='stack_plot'><img src='!ploturl!stackplot-3782018093-91095845.svg' alt='STACK auto-generated plot of x^2 with parameters [[x,-1,1],[y,0,2]]' width='450' /></div></html> "
], display = [

 \mbox{ <html><div class='stack\_plot'><img src='!ploturl!stackplot-3782018093-91095845.svg' alt='STACK auto-generated plot of x^2 with parameters [[x,-1,1],[y,0,2]]' width='450' /></div></html> }
]
],
] ]
(%o3) true

Slasharguments are working, as I can access image directly: <web_url>/question/type/stack/plot.php/stackplot-3782019698-91095845.svg

sangwinc commented 5 years ago

Hmm, that looks like a genuine timeout then! Are you on a server, or using a home PC for testing?

vahem2lu commented 5 years ago

Using qemu VM in a server (if that makes a difference). I can set timeout to 500 seconds as well, nothing changes.

On 9. Nov 2019, at 15:56, Chris Sangwin notifications@github.com wrote:

 Hmm, that looks like a genuine timeout then! Are you on a server, or using a home PC for testing?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub, or unsubscribe.

[ { "@context": "http://schema.org", "@type": "EmailMessage", "potentialAction": { "@type": "ViewAction", "target": "https://github.com/maths/moodle-qtype_stack/issues/513?email_source=notifications\u0026email_token=ADXMTBJMLWDYNKUA43NWH6DQS26MFA5CNFSM4JJRWNO2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDUGVSI#issuecomment-552102601", "url": "https://github.com/maths/moodle-qtype_stack/issues/513?email_source=notifications\u0026email_token=ADXMTBJMLWDYNKUA43NWH6DQS26MFA5CNFSM4JJRWNO2YY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOEDUGVSI#issuecomment-552102601", "name": "View Issue" }, "description": "View this Issue on GitHub", "publisher": { "@type": "Organization", "name": "GitHub", "url": "https://github.com" } } ]

rca19 commented 4 years ago

I have the same issuse on a production server. Using Arch Linux and Maxima 5.43.0 and gnuplot 5.2 patchlevel 8 from Arch repository.

The problem shows in CAS chat and in health check script.

When I input {@plot(x^3,[x,-1,1])@} in CAS text box, I get the following in the CAS result (with plotdebug set to TRUE):

Maxima 5.43.0 http://maxima.sourceforge.net using Lisp SBCL 2.0.0 Distributed under the GNU Public License. See the file COPYING. Dedicated to the memory of William Schelter. The function bug_report() provides bug reporting information. (%i1) WARNING: redefining MAXIMA::OPAPPLY in DEFMACRO WARNING: redefining MAXIMA::OPCONS in DEFMACRO define: warning: redefining the built-in function intervalp

; file: /srv/http/moodle/question/type/stack/stack/maxima/stacktex.lisp ; in: DEFUN MTELL ; (EQ MAXIMA::$STACK_MTELL_QUIET MAXIMA::$TRUE) ; ; caught WARNING: ; undefined variable: MAXIMA::$STACK_MTELL_QUIET ; ; compilation unit finished ; Undefined variable: ; $STACK_MTELL_QUIET ; caught 1 WARNING condition warning: variable simp (declared type boolean) assigned type any. define: warning: redefining the built-in function texnumformat warning: encountered undefined variable stackintfmt in translation. [ STACK-Maxima started, library version 2019121800 ] (%o0) "/srv/moodledata/stack/maximalocal.mac" (%i1) [STACKSTART Locals= [
-1=[ error= [ ], key = [ __stackmaximaversion ] , value = [ 2019121800 ], dispvalue = [ 2019121800 ], display = [ 2019121800 ] ],
0=[ error= [ set terminal svg size 450, 300
[[plot_format,gnuplot_pipes]] [x^3,[x,-1,1],[xlabel,""],[ylabel,""],[legend,false]] ["gnuplot /srv/moodledata/stack/tmp/stackplot-3787857345-34984027.plt","rm /srv/moodledata/stack/tmp/stackplot-3787857345-34984027.plt"] The CAS timed out. ] ] ] ]

The PLT file in the STACK tmp directory is produced immediately, the SVG file appears in plots directory after 5 minutes delay (and always after this time). The output from the top command at this time shows that sbcl is using 100% time of one processor core:

PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                              
450031 http      20   0 1224812  89696  26368 R 100.0   0.1   0:19.76 sbcl

I have also tried to do the same with maxima 5.38.1 compiled from source on the same server with similar effect. The only difference was that the process using the cpu was "maxima", not "sbcl"

However, the same command typed directly into maxima (started as user http and after loading maximalocal.mac) has an immediate effect - the files are produced in a split second.

The output from maxima terminal (started with "sudo -u http maxima") is:

(%i1) load("maximalocal.mac"); WARNING: redefining MAXIMA::OPAPPLY in DEFMACRO WARNING: redefining MAXIMA::OPCONS in DEFMACRO define: warning: redefining the built-in function intervalp

; file: /srv/http/moodle/question/type/stack/stack/maxima/stacktex.lisp ; in: DEFUN MTELL ; (EQ MAXIMA::$STACK_MTELL_QUIET MAXIMA::$TRUE) ; ; caught WARNING: ; undefined variable: MAXIMA::$STACK_MTELL_QUIET ; ; compilation unit finished ; Undefined variable: ; $STACK_MTELL_QUIET ; caught 1 WARNING condition warning: variable simp (declared type boolean) assigned type any. define: warning: redefining the built-in function texnumformat warning: encountered undefined variable stackintfmt in translation. [ STACK-Maxima started, library version 2019121800 ] (%o0) "maximalocal.mac" (%i1) plot(-x^3,[x,-1,2]);

set terminal svg size 450, 300
[[plot_format,gnuplot_pipes]] [-x^3,[x,-1,2],[xlabel,""],[ylabel,""],[legend,false]] ["gnuplot /srv/moodledata/stack/tmp/stackplot-3787855086-99604678.plt","rm /srv/moodledata/stack/tmp/stackplot-3787855086-99604678.plt"] (%o1) " <html><div class='stack_plot'><img src='!ploturl!stackplot-3787855086-99604678.svg' alt='STACK auto-generated plot of -x^3 with parameters [[x,-1,2]]' width='450' /></div></html> " (%i2)

Plots were working fine before server upgrade (on Debian 9 with Moodle 3.6 and STACK 4.2.2). I do not understand the difference between calling "plot" from maxima terminal and the php script. I would be grateful for any hints.

otatarintseva commented 4 years ago

It seems like I have similar issue.

I tried to create new quiz question with settings like in the documentation example: https://stack2.maths.ed.ac.uk/demo2018/question/type/stack/doc/doc.php/Authoring/Authoring_quick_start.md, but can not save it, because it returns TIMEDOUT under "Model answer" input field. I tried create the same question from the beginning and prepared it quickly to avoid session timing out. Also logged out and logged in and tried again - the same error appeared.

I tested it on Moodle 3.8. $version = 2019111802.00; $release = '3.8.2 (Build: 20200309)';

Plugin version: 2020042000. PHP version 7.2

vahem2lu commented 4 years ago

Any ideas @sangwinc ?

sangwinc commented 4 years ago

Sorry, I don't know why this isn't working and I don't have an easy way (i.e. available server of that spec) to investigate further. Not sure where to take this.

vahem2lu commented 4 years ago

Maybe you could try ArchLinux installation in your VirtualBox to see if this is Arch Linux dependant error?

aharjula commented 4 years ago

Always funny when someone just asks one to test installing Arch... Not exactly the easiest system to install... and really easy to tune it in interesting ways. Is it tuned to be a server or a desktop and are there interesting services intercepting file-operations etc. difficult to know especially if someone has taken a shortcut and installed that Arch using some install-script, there are just too many ways of installing it for us to even consider checking what could possibly have gone wrong.

Anyway, I have Arch in one of my machines and current STACK, with freshly from default sources through pacman installed Maxima and gnuplot, it just works. Although I would never even think about running a STACK server on Arch or any other rolling distribution, so I would recommend considering whether you even want to find out what is broken in that install and instead consider if you should pick something else as the platform. Just try something stabler like FreeBSD :)

Also if the health check script works and generates images (clear the cache just in case) then everything should work. But you still can write question-code that just times out due to being too much for the system, always check for that.

Note that 5.43.x versions of Maxima are not currently supported, even though they seem to work so compiling your own (with a supported version) is always an option as is configuring for some other LISP when compiling that Maxima. Different LISPs might handle IO (file and process) differently so that might help. Also if you compile your own Maxima do remember to tell STACK about it so that it does not automatically try to use something coming from a package.

aharjula commented 4 years ago

And in case someone wonders what is the difference between command-line calls with Maxima and the web-server calling Maxima it is simply the execution environment for those commands that changes everything also the web-server might impose additional security context for those calls. Just run system("env"); in your command-line Maxima and think hard whether that result is likely to be the same when the web-server executes that Maxima. Note that for security reasons STACK won't let you run that command through STACK, so if you really want to know the server environment, feel free to kill that bit of security on your own, just remember to restore it, for "reasons" I will not tell what to disable.

rca19 commented 4 years ago

Dear Matti, Thank you for the reply. I will give it another try - with re-installing maxima ant gnuplot and using the last STACK. But the problem is that I do not get any plots on the health-check page. Most astonishingly, the plots are actually produced - the gnuplot file in the temp folder of STACK, and the svg file in the plots. The gnuplot file appears immediately, but then ... there is a 5 minute delay (and always exactly the same delay - telling from file creation time) before the svg image appears. During this time the maxima process is taking 100% of CPU (one core). That is a bit confusing because, I thought, the output of maxima is the first file, which should be then passed to gnuplot and shown on page. I have checked the 'env' - all paths and execution permissions are correct (the svg files are produced). I just cannot find the cause of the delay. Perhaps I should dig deeper as you suggested. You are right with the Arch on production server, it was not my choice. I had no problems of this kind on Debian and Ubuntu. Regards, Radosław Cechowicz

On Thu, 21 May 2020 at 16:51, Matti Harjula notifications@github.com wrote:

Always funny when someone just asks one to test installing Arch... Not exactly the easiest system to install... and really easy to tune it in interesting ways. Is it tuned to be a server or a desktop and are there interesting services intercepting file-operations etc. difficult to know especially if someone has taken a shortcut and installed that Arch using some install-script, there are just too many ways of installing it for us to even consider checking what could possibly have gone wrong.

Anyway, I have Arch in one of my machines and current STACK, with freshly from default sources through pacman installed Maxima and gnuplot, it just works. Although I would never even think about running a STACK server on Arch or any other rolling distribution, so I would recommend considering whether you even want to find out what is broken in that install and instead consider if you should pick something else as the platform. Just try something stabler like FreeBSD :)

Also if the health check script works and generates images (clear the cache just in case) then everything should work. But you still can write question-code that just times out due to being too much for the system, always check for that.

Note that 5.43.x versions of Maxima are not currently supported, even though they seem to work so compiling your own (with a supported version) is always an option as is configuring for some other LISP when compiling that Maxima. Different LISPs might handle IO (file and process) differently so that might help. Also if you compile your own Maxima do remember to tell STACK about it so that it does not automatically try to use something coming from a package.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/maths/moodle-qtype_stack/issues/513#issuecomment-632129862, or unsubscribe https://github.com/notifications/unsubscribe-auth/AN2CO7RCJTP66RAJQHZ5DJ3RSU5X5ANCNFSM4JJRWNOQ .

-- Radosław Cechowicz

aharjula commented 4 years ago

Never heard of anyone having that delay before, if I had to guess it ould be something else processing that file when it gets written and timing out after 5 minutes, maybe the shell that Maxima uses to call gnuplot is different in the web-servers environment and does something odd, or could be that the file-system to which it gets written is somehow slow or does not respond with sensible completion signals. Maxima probably keeps the load high as it waits/polls for that gnuplot call to complete. Might be that the LISP version in use does not work well with whatever other environment that system has.

It is very difficult for us to do any debugging as we have no idea what could cause that, you should really look at any other software present in that system as well as the nature of the file-system used for storing those plots. Given that I could not replicate it on Arch points to something non-standard affecting your system.

Random shot at the dark, gnuplot vs. gnuplot-nox might be something worth testing. The latter obviously being the better one, as the server case most definitely has no X.

Lennart-Kramer commented 4 years ago

If you're using sbcl, what are your rlimits, especially the RLIMIT_NOFILE limit (which you can find out with ulimit -H -n)?

When forking a new process, sbcl tries to close all filedescriptors, which it does by looping over every integer until RLIMIT_NOFILE is reached and calling close on it, which can take a long time if the rlimit is high.

You can typically set them per-user in /etc/security/limits.conf (and you want to set the hard limits, since sbcl appears to undo the soft limits when forking).

rca19 commented 1 year ago

Yes, the suggestion of Lennart-Kramer was correct! It solved the problem!

In my case, the RLIMIT_NOFILE imposed on the httpd process in systemd's httpd.service file was "infinity" (which translated to "Max open files = 1073741816" in the /proc/pid file), maxima and sbcl, started by http user inherited the same values. So it turns out sbcl was working hard closing over 107 Million files each time it was called, which explains the 5 minute delay! The problem dissapeared after changing LimitNOFILE in the httpd.service to some reasonable value (like 1024) and restarting the service.

Information that helped me to pinpoint the problem: a) limits set in limits.conf are ignored by systemd (this post: https://unix.stackexchange.com/questions/345595/how-to-set-ulimits-on-service-with-systemd, and this post: https://serverfault.com/questions/628610/increasing-nproc-for-processes-launched-by-systemd-on-centos-7/678861#678861) b) information that process limits are published in /proc/pid files (found somewhere else).