On 15/02/2015, at 9:03 PM, Paul Royik <[email protected]> wrote:
> How do you know that it runs too long? In explained the log output previously and what was happening. If you go back far enough in the logs even before what you provided you will see some messages like: [Fri Feb 06 12:39:06.254056 2015] [wsgi:info] [pid 9731:tid 140178879313664] mod_wsgi (pid=9731): Daemon process request time limit exceeded, stopping process 'localhost:20241'. [Fri Feb 06 12:39:06.254108 2015] [wsgi:info] [pid 9731:tid 140179136616192] mod_wsgi (pid=9731): Shutdown requested 'localhost:20241'. [Fri Feb 06 12:39:06.286339 2015] [wsgi:info] [pid 9731:tid 140179136616192] mod_wsgi (pid=9731): Dumping stack trace for active Python threads. [Fri Feb 06 12:39:06.286359 2015] [wsgi:info] [pid 9731:tid 140179136616192] mod_wsgi (pid=9731): Thread 140178316318464 executing file "/usr/local/lib/python2.7/threading.py", line 147, in acquire [Fri Feb 06 12:39:06.286363 2015] [wsgi:info] [pid 9731:tid 140179136616192] mod_wsgi (pid=9731): called from file "/home/simamura/lib/python2.7/sympy/core/compatibility.py", line 851, in wrapper, [Fri Feb 06 12:39:06.286366 2015] [wsgi:info] [pid 9731:tid 140179136616192] mod_wsgi (pid=9731): called from file "/home/simamura/lib/python2.7/sympy/core/cache.py", line 89, in wrapper, [Fri Feb 06 12:39:06.286369 2015] [wsgi:info] [pid 9731:tid 140179136616192] mod_wsgi (pid=9731): called from file "/home/simamura/lib/python2.7/sympy/core/operations.py", line 127, in _matches_commutative, [Fri Feb 06 12:39:06.286372 2015] [wsgi:info] [pid 9731:tid 140179136616192] mod_wsgi (pid=9731): called from file "/home/simamura/lib/python2.7/sympy/core/mul.py", line 808, in matches, [Fri Feb 06 12:39:06.286375 2015] [wsgi:info] [pid 9731:tid 140179136616192] mod_wsgi (pid=9731): called from file "/home/simamura/lib/python2.7/sympy/core/add.py", line 358, in _matches_simple, [Fri Feb 06 12:39:06.286378 2015] [wsgi:info] [pid 9731:tid 140179136616192] mod_wsgi (pid=9731): called from file "/home/simamura/lib/python2.7/sympy/core/operations.py", line 127, in _matches_commutative, So it says that request time limit was exceeded. This is followed by stack dumps for what all the request threads were doing. In the part you did show, they both are stuck in: [Sat Feb 14 19:58:00.261118 2015] [wsgi:info] [pid 12528:tid 139862016030464] mod_wsgi (pid=12528): Thread 139861715523328 executing file "/usr/local/lib/python2.7/threading.py", line 147, in acquire [Sat Feb 14 19:58:00.261120 2015] [wsgi:info] [pid 12528:tid 139862016030464] mod_wsgi (pid=12528): called from file "/home/simamura/lib/python2.7/sympy/core/compatibility.py", line 851, in wrapper, [Sat Feb 14 19:58:00.261122 2015] [wsgi:info] [pid 12528:tid 139862016030464] mod_wsgi (pid=12528): called from file "/home/simamura/lib/python2.7/sympy/core/cache.py", line 89, in wrapper, [Sat Feb 14 19:58:00.261125 2015] [wsgi:info] [pid 12528:tid 139862016030464] mod_wsgi (pid=12528): called from file "/home/simamura/lib/python2.7/sympy/core/mul.py", line 373, in _gather, [Sat Feb 14 19:58:00.261127 2015] [wsgi:info] [pid 12528:tid 139862016030464] mod_wsgi (pid=12528): called from file "/home/simamura/lib/python2.7/sympy/core/mul.py", line 98, in flatten, That is, they are both waiting on a thread lock. This suggests to me that the code isn't possibly dealing with locking properly, or a lock is held for a very long time while in some certain section and blocking other threads from running and so why they are delayed and take so long. > No more than 300 seconds as I wrote in conf file (socket-timeout and > request-timeout). > > I can not control it thoroughly. > def algo(): > do_something() > invoke_external_library() # this could run slighlty longer, so timeout is > not precise > check_timeout() > algo() So the thing that takes the unpredictable amount of time and you need to interrupt is not even your code? Graham > On Sunday, February 15, 2015 at 11:36:05 AM UTC+2, Graham Dumpleton wrote: > So we are back the fact that your requests are still running too long and > however you have set up the timeout check isn't working. > > Have you added print() debug statements in your code to validate that the die > on timeout check is even being run regularly? > > To be able to distinguish each request thread, you can include the output of > threading.currentThread() on the print statements. > > Graham > > On 15/02/2015, at 8:19 PM, Paul Royik <[email protected]> wrote: > >> [Sat Feb 14 19:58:00.261309 2015] [wsgi:info] [pid 12528:tid >> 139862016030464] mod_wsgi (pid=12528): called from file >> "/home/simamura/lib/python2.7/mod_wsgi/server/__init__.py", line 1137, in >> handle_request. >> [Sat Feb 14 19:58:05.245850 2015] [wsgi:info] [pid 12528:tid >> 139861541500672] mod_wsgi (pid=12528): Aborting process 'localhost:20241'. >> [Sat Feb 14 19:58:05.245889 2015] [wsgi:info] [pid 12528:tid >> 139861541500672] mod_wsgi (pid=12528): Exiting process 'localhost:20241'. >> [Sun Feb 15 01:58:05.352861 2015] [wsgi:error] [pid 11272:tid >> 139862014424832] [client 127.0.0.1:48193] Truncated or oversized response >> headers received from daemon process 'localhost:20241': >> /home/simamura/webapps/django_math/express/htdocs/calculators, referer: >> http://www.emathhelp.net/calculators/calculus-2/integral-calculator/ >> [Sun Feb 15 01:58:05.352890 2015] [wsgi:error] [pid 11272:tid >> 139862015223552] [client 127.0.0.1:48563] Truncated or oversized response >> headers received from daemon process 'localhost:20241': >> /home/simamura/webapps/django_math/express/htdocs/calculators, referer: >> http://www.emathhelp.net/calculators/calculus-2/integral-calculator/ >> [Sun Feb 15 01:58:05.352958 2015] [wsgi:error] [pid 11272:tid >> 139861948524288] [client 127.0.0.1:48240] Truncated or oversized response >> headers received from daemon process 'localhost:20241': >> /home/simamura/webapps/django_math/express/htdocs/calculators, referer: >> http://www.emathhelp.net/calculators/calculus-2/integral-calculator/ >> [Sun Feb 15 01:58:05.352992 2015] [wsgi:error] [pid 11272:tid >> 139862015489792] [client 127.0.0.1:48440] Truncated or oversized response >> headers received from daemon process 'localhost:20241': >> /home/simamura/webapps/django_math/express/htdocs/calculators, referer: >> http://www.emathhelp.net/calculators/calculus-2/integral-calculator/ >> [Sun Feb 15 01:58:05.353008 2015] [wsgi:error] [pid 11666:tid >> 139862014957312] [client 127.0.0.1:48329] Truncated or oversized response >> headers received from daemon process 'localhost:20241': >> /home/simamura/webapps/django_math/express/htdocs/calculators, referer: >> http://www.emathhelp.net/calculators/calculus-2/integral-calculator/ >> [Sun Feb 15 01:58:05.353015 2015] [wsgi:error] [pid 11272:tid >> 139862014691072] [client 127.0.0.1:48620] Truncated or oversized response >> headers received from daemon process 'localhost:20241': >> /home/simamura/webapps/django_math/express/htdocs/calculators, referer: >> http://www.emathhelp.net/calculators/calculus-2/integral-calculator/ >> [Sun Feb 15 01:58:05.353081 2015] [wsgi:error] [pid 11272:tid >> 139861949323008] [client 127.0.0.1:48778] Truncated or oversized response >> headers received from daemon process 'localhost:20241': >> /home/simamura/webapps/django_math/express/htdocs/calculators, referer: >> http://www.emathhelp.net/calculators/calculus-2/integral-calculator/ >> [Sun Feb 15 01:58:05.353081 2015] [wsgi:error] [pid 11666:tid >> 139861948790528] [client 127.0.0.1:48735] Truncated or oversized response >> headers received from daemon process 'localhost:20241': >> /home/simamura/webapps/django_math/express/htdocs/calculators, referer: >> http://www.emathhelp.net/calculators/calculus-2/integral-calculator/ >> [Sun Feb 15 01:58:05.353096 2015] [wsgi:error] [pid 11666:tid >> 139862015223552] [client 127.0.0.1:48792] Truncated or oversized response >> headers received from daemon process 'localhost:20241': >> /home/simamura/webapps/django_math/express/htdocs/calculators, referer: >> http://www.emathhelp.net/calculators/calculus-2/integral-calculator/ >> [Sun Feb 15 01:58:05.972993 2015] [wsgi:info] [pid 24792:tid >> 139862016030464] mod_wsgi (pid=12528): Process 'localhost:20241' has died, >> deregister and restart it. >> [Sun Feb 15 01:58:06.081051 2015] [wsgi:info] [pid 24792:tid >> 139862016030464] mod_wsgi (pid=12528): Process 'localhost:20241' has been >> deregistered and will no longer be monitored. >> [Sun Feb 15 01:58:06.081333 2015] [wsgi:info] [pid 23028:tid >> 139862016030464] mod_wsgi (pid=23028): Starting process 'localhost:20241' >> with threads=10. >> [Sun Feb 15 01:58:06.163910 2015] [wsgi:info] [pid 23028:tid >> 139862016030464] mod_wsgi (pid=23028): Python home /usr/local. >> [Sun Feb 15 01:58:06.163937 2015] [wsgi:info] [pid 23028:tid >> 139862016030464] mod_wsgi (pid=23028): Initializing Python. >> [Sun Feb 15 01:58:06.534740 2015] [wsgi:info] [pid 23028:tid >> 139862016030464] mod_wsgi (pid=23028): Attach interpreter ''. >> [Sun Feb 15 01:58:06.549849 2015] [wsgi:info] [pid 23028:tid >> 139862016030464] mod_wsgi (pid=23028): Imported 'mod_wsgi'. >> [Sun Feb 15 01:58:06.549942 2015] [wsgi:info] [pid 23028:tid >> 139862016030464] mod_wsgi (pid=23028, process='localhost:20241', >> application=''): Loading WSGI script >> '/home/simamura/webapps/django_math/express/handler.wsgi'. >> [Sun Feb 15 02:06:36.476939 2015] [core:info] [pid 11272:tid >> 139861948524288] [client 127.0.0.1:56156] AH00128: File does not exist: >> /home/simamura/webapps/math_root/browserconfig.xml >> >> >> And that's all. >> >> On Sunday, February 15, 2015 at 10:11:25 AM UTC+2, Graham Dumpleton wrote: >> Provide me with the logging from a period before the restart until a period >> after. >> >> The log can be very informative if you know what to look for. >> >> Graham >> >> On 15/02/2015, at 6:43 PM, Paul Royik <[email protected]> wrote: >> >>> I actually have custom error 500 page. This means, that when Django throws >>> error, custom page should be shown. >>> But it is not the case. Standard white-background apache page is shown. >>> So, I think that problem is not in Django exception. Otherwise Django would >>> show custom page, which is not the case. >>> In logs I saw only that server was restarted. >>> Can I somehow tune logging, so that real error is written? >>> >>> On Sunday, February 15, 2015 at 2:44:50 AM UTC+2, Graham Dumpleton wrote: >>> >>> On 15/02/2015, at 10:53 AM, Paul Royik <[email protected]> wrote: >>> >>> > I already tried this approach. >>> > >>> > It seems good. >>> > But when I tested it on server, by simultaneously executing page on two >>> > different computers, it gave me 500 error. >>> > >>> > How this can be explained? Again something with apache? Logs didn't show >>> > anything. But I noticed again serious memory usage. And this happens only >>> > when I use code for limiting time. >>> >>> >>> Some tips for you about ensuring you get the best help. >>> >>> Stop discarding the message content for the message you are replying to. It >>> can be frustrating to have to keep going back to old messages to see what >>> was said originally and what you may be following up to, especially when on >>> a phone. When asking questions on mailing list, let the person you are >>> asking questions of decide what can be discarded from the message chain as >>> they will know better what should be kept in the message to provide easy >>> access to important information for context. >>> >>> When you reply to say you are have a new error, provide the actual code you >>> were using exactly at the time you had the error. Saves the person who is >>> helping you having to go back and ask for it if it is unclear what code you >>> were using. >>> >>> Your messages here and on StackOverflow show that you play around with the >>> example code I am giving you and I have reduced confidence you were running >>> with the code I suggested at the time of the problem you are now relating >>> to. >>> >>> If you are getting 500 errors and nothing is being logged, it is because >>> Django is capturing the exception and converting it to a generic 500 error >>> response page. Configure Django to send you emails with the details of the >>> exceptions. If you are on a local system, then set DEBUG=True in the Django >>> settings so the details of the error are shown in response that goes back >>> to the browser. >>> >>> As to the code, I did test it this time, including under mod_wsgi with 20 >>> request threads and hitting it with concurrent and successive requests with >>> a benchmarking tool. I saw no issues and it appeared to behave as I would >>> expect. >>> >>> So in a test2.py file I had: >>> >>> import time >>> import functools >>> import threading >>> >>> def time_limit(seconds): >>> def decorator(func): >>> func.info = threading.local() >>> def check_timeout(): >>> if time.time() > func.info.end_time: >>> raise RuntimeError('timeout') >>> >>> func.check_timeout = check_timeout >>> >>> @functools.wraps(func) >>> def wrapper(*args, **kwargs): >>> print 'hasattr counter', hasattr(func.info, 'counter') >>> if not hasattr(func.info, 'counter'): >>> print 'init counter to 0' >>> func.info.counter = 0 >>> if func.info.counter == 0: >>> func.info.end_time = time.time() + seconds >>> print 'counter', func.info.counter >>> func.info.counter += 1 >>> try: >>> return func(*args, **kwargs) >>> finally: >>> func.info.counter -= 1 >>> >>> return wrapper >>> >>> return decorator >>> >>> @time_limit(5) >>> def algorithm(limit, nest=0): >>> algorithm.check_timeout() >>> print 'sleep' >>> time.sleep(1.0) >>> if nest == limit: >>> print 'return' >>> return >>> algorithm(limit, nest+1) >>> >>> In serial2.py I had a straight serialised test: >>> >>> from test2 import algorithm >>> >>> try: >>> algorithm(3) >>> except RuntimeError: >>> print 'timeout' >>> >>> try: >>> algorithm(10) >>> except RuntimeError: >>> print 'timeout' >>> >>> try: >>> algorithm(10) >>> except RuntimeError: >>> print 'timeout' >>> >>> And then in hello2.wsgi I had it used by a WSGI application. >>> >>> from test2 import algorithm >>> >>> def application(environ, start_response): >>> status = '200 OK' >>> output = b'Hello World!' >>> >>> algorithm(1) >>> >>> response_headers = [('Content-type', 'text/plain'), >>> ('Content-Length', str(len(output)))] >>> start_response(status, response_headers) >>> >>> return [output] >>> >>> In the latter case I ran mod_wsgi-express against it as: >>> >>> mod_wsgi-express start-server hello2.wsgi --port 8002 --threads=20 >>> >>> and then hit it with ab as: >>> >>> ab -n 100 -c 15 http://localhost:8002/ >>> >>> In this case it wasn't designed to timeout anything, but that should not be >>> a concern as the counter initialisation is still being tested. >>> >>> Do note that if you did cut and paste that last code, I did change the >>> exception type. >>> >>> Anyway, the best thing to do is setup Django so that it provides the >>> details of the exception it captured but then effectively discarded because >>> it converted it to a 500 page. > > > -- > You received this message because you are subscribed to the Google Groups > "modwsgi" group. > To unsubscribe from this group and stop receiving emails from it, send an > email to [email protected]. > To post to this group, send email to [email protected]. > Visit this group at http://groups.google.com/group/modwsgi. > For more options, visit https://groups.google.com/d/optout. -- You received this message because you are subscribed to the Google Groups "modwsgi" group. To unsubscribe from this group and stop receiving emails from it, send an email to [email protected]. To post to this group, send email to [email protected]. Visit this group at http://groups.google.com/group/modwsgi. For more options, visit https://groups.google.com/d/optout.
