Debugging two http_server inside docker containers

Help!
1

I’m using: SWI-Prolog (threaded, 64 bits, version 10.0.2)

I try to debug two containers running http_server, where one functions as a proxy calling the other using http_post.

Every 30 requests or so I get such an error on the proxy: (the browser gets HTTP-500)
url `‘http://akrido:8081/analinioj’’ does not exist (status(503,Service Unavailable))

This is coming back as fast as the valid answers (150ms). So it seems there is no timeout involved. Could some kind of network issue. The fast return hints on a client (i.e. proxy) side issue. I do not use the connection(keep_alive) option in the http_post - not sure what would be the best approach in this proxy scenario.

I tried to debug the http requests using the containers log (stdout) but I don’t see the output. Where it is going to? I tried those two commands:

[swipl,-s,analizo-servo.pl,-g,debug(http(request)),-g,daemon,-t,halt(1),--,--workers=10,--port=8081,--no-fork]
% Started server at http://localhost:8081/

[swipl,-s,analizo-servo.pl,-g,daemon,-t,halt(1),--,--workers=10,--port=8081,--no-fork,--debug='http(request)']
% Started server at http://localhost:8081/

How I would debug this issue? Any hint where to look specifically would help me.

Thank you,
Wolfram.

2

503 is a resource error, no?

  ?- [library(http/http_error)].

This should cause a backtrace to be printed on HTTP server errors.

3

Ah thank you, this helps a bit further. Now I get this in the browser:

~~~
url `‘http://akrido:8081/analinioj’’ does not exist (status(503,Service Unavailable))\nIn:\n
[25] throw(error(existence_error(url,‘http://akrido:8081/analinioj’),context(_39148,…)))\n
[23] http_open:try_http_proxy(direct,[uri(‘http://akrido:8081/analinioj’),…|…],_39184,[headers(_39212),…])
at /usr/lib/swipl/library/ext/http/http/http_open.pl:512\n
[21] http_client:http_get(‘http://akrido:8081/analinioj’,_39250,[post(…)])
at /usr/lib/swipl/library/ext/http/http/http_client.pl:145\n
[19] redakt…:565\n
[6] httpd_wrapper:handler_with_output_to(http_unix_daemon:http_dispatch,101,[pool(…),…|…],current_output,_39620)
at /usr/lib/swipl/library/ext/http/http/http_wrapper.pl:312\n
[5] httpd_wrapper:handler_with_output_to(http_unix_daemon:http_dispatch,101,[pool(…),…|…],(0x55d58555a400),_39680)
at /usr/lib/swipl/library/ext/http/http/http_wrapper.pl:322\n\n
Note: some frames are missing due to last-call optimization.\n
Re-run your program in debug mode (:- debug.) to get more detail.
~~~

Method=direct means “don’t use a proxy”, right? This would be ok so far. Not fully sure, but this could be the place where the error is catched in http_open:try_http_proxy

~~~

catch(send_rec_header(StreamPair, Stream, HostPort,
RequestURI, Parts, Options),
error(E,_),
keep_alive_error(E))

~~~

Seems I have to dig a bit deeper at this place tomorrow.

Regards,
Wolfram.

4

But, this is the client that gets a 503 from the other side. It is that other side that is broken. 503 means resource error. That can mean the server is overloaded or, in particular if it is also a Prolog server, it runs out of stack. If the server is also Prolog, load http_error into that one as well.

5

Hi Jan,

I could not get debug output into the container log using the --debug command line option so far, but adding a hook for user:exception I now see random crashes of the worker threads:

thread: httpd@8081_9, exc: undefined_predicate, ctx: thread:same_length/2,
thread: httpd@8081_7, exc: undefined_predicate, ctx: thread:must_be/2,
thread: <thread>(17,0x562c09d9e280), exc: undefined_predicate, ctx: analizilo:maplist/3,
thread: <thread>(17,0x562c09d9e280), exc: undefined_global_variable, ctx: $inprint_message,
thread: <thread>(17,0x562c09d9e280), exc: undefined_predicate, ctx: gramatiko:aggregate/3,
thread: <thread>(17,0x562c09d9e280), exc: undefined_global_variable, ctx: $autoload_disabling,
...

It appears that there are workers added until the resources in my container are exhausted around 30 workers and than workers start crashing. I did not see those http-503 errors before (last year) and apparantly dead workers not always cause the http-503 on the client side. So I suppose the equilibrium between resources, load average, workers, timing was different some months back.

I see there is a max_workers option hidden here: SWI-Prolog -- library(http/http_dyn_workers): Dynamically schedule HTTP workers.
I could not find it with the usual search, and it is not here as well:
SWI-Prolog -- http_daemon/0
but using Google I finally found it :slight_smile:

What is the proper way to set this to a lower value? I tried both:

:- set_setting(http:max_workers, 10).

:- multifile http:max_workers/1.
:- dynamic   http:max_workers/1.
http:max_workers(10).

but with htop I still see more workers being created under load, and the exceptions keep being raised. What am I missing?

Kind regards,
Wolfram.

6

That is not relevant. What you are seeing are traps that trigger the autoloader. If you define it, make sure it fails, so the system default does its work.

That is ok when loaded after loading http_dyn_workers.pl. You can also use

:- set_setting_default(http:max_workers, 10).

Which you can load before loading the code. In any case, use setting/2 to verify the effective value.

I think you should still load http_errors.pl into the server. That causes the server to include the stack trace in the 503 message. Now, this is by default just mapped to an existence_error (should be a resource_error). If you use the status_code(Code) option of http_open/3 on the client side, it will report 503 and you can read the document the normal way. The content is JSON if the request asks for application/json or HTML if text/html or nothing is specified.

Note there is also a notion of worker pools for the HTTP server. You can assign a handler to a pool and next define the pool properties, such as its maximum number of threads and max stack size. Finally, you can specify what to do if the pool is full: reply with 503 or wait.

7

Hi Jan,

If you use the status_code(Code) option of [http_open/3](plweb
doc_for?object=http_open/3 “Open the data at the HTTP server as a Prolog stream.”) on the client side, it will report 503 and you can read the document the normal way.

This brought the issue into light now. Seems I do not handle a call_with_inference_limit properly at some place in my code:

In:<br>
    [41] system:'$inference_limit'(1000000, _686)<br>
    [40] '$syspreds':call_with_inference_limit(&lt;compound (:)/2&gt;, 1000000, _714)<br>
    [39] gramatiko:analyze_pt([length:9], _746, _748, _750)<br>
    [38] system:'&lt;meta-call&gt;'(&lt;compound (:)/2&gt;)<br>
    [37] solution_sequences:distinct_gen(&lt;trie&gt;(0x5622bd0f5810), &lt;compound (:)/2&gt;, &lt;compound v/3&gt;)<br>

Thank you for your support. I think I now got a better understanding of the http worker handling as well.

Kind regards,
Wolfram.

8

ok, I tried to look into the issue a bit more, and I’m a bit confused now:

The request itself is getting a JSON with some lines of text, which it analyzes using concurrent_maplist. The inference_limit protection is around the analysis of the single words. There is one word in the text, which cannot be analyzed, so hitting the inference limit there is expected. But usually this works fine.

I now wrote a shell script which calls the URL 100 times (always with the same JSON body) in a parallelized way. About one out of 100 requests returns the http 503:

{
  "code":503,
  "message":"Service unavailable: error(resource_error(stack),stack_overflow{choicepoints:8,depth:31,environments:22,globalused:63,localused:3,stack:[frame(31,system:'$inference_limit'(1000000,_758),[]),frame(30,'$syspreds':call_with_inference_limit((:)/2,1000000,_786),[]),frame(29,gramatiko:analyze_pt([2],_818,_820,_822),[]),frame(28,system:'<meta-call>'((:)/2),[]),frame(27,solution_sequences:distinct_gen(<trie>(0x56028afb3550),(:)/2,v/3),[])],stack_limit:1048576,trailused:6})"
}

If I understand the hint error(resource_error(stack) right, I did not hit the inference limit, but the stack limit here. When I increase stack-limit via command line to 4g I get basically the same result. So I have some doubt if I really hit the stack limit here.

I added a call returning statistics(stack,St) in between, and it returns values between 1 and 3 MB (supposing the value is in bytes). Is there a way to get more detailed information about the issue I hit here?

Kind regards,
Wolfram.

9

To be sure, verify the limit. The commanline option sets the limit for the main thread. Normally all threads should inherit from that, but the rules are not so simple.

But, 100 concurrent jobs, each using concurrent_maplist/2 may get you a lot of threads. AFAIK, you also get an out-of-stack if malloc() fails to allocate the stack. Could it be you are running out of memory? Most likely this is a dubious design. Having significantly more computing threads than cores merely slows things down. There are plenty of ways to limit resource usage. The best choice depends on a lot of parameters though. Using thread pools is probably a good step. That provides more control. Next, you may want to adjust the concurrency used by concurrent_maplist/2 depending on the number of already running threads and/or HTTP workers.

10

Hi Jan,

But, 100 concurrent jobs, each using [concurrent_maplist/2](plweb
doc_for?object=concurrent_maplist/2 “Concurrent version of maplist/2.”) may get you a lot of
threads.

I have very few concurrent users and wasn’t aware before, that the worker threads may increase up to hundred. That’s why I think hard limiting the worker threads, is the right option.

In my application, each request gets max. 20 lines, so when analyzing a text with 200 lines I have 10 workers in parallel running 20 threads with concurrent_maplist, so max. 200 threads total.

But anyway, using maplist instead of concurrent_maplist did not change the outcome.

AFAIK, you also get an out-of-stack if malloc() fails to allocate the stack. Could it be you are running out of memory?

Yes, I thought about this as well, as I could not reproduce the http 503 with http_server locally outside a container (for easier debugging). But a docker stats during my test run shows, I have plenty of memory left.

CONTAINER ID   NAME          CPU %     MEM USAGE / LIMIT     MEM %     NET I/O         BLOCK I/O    PIDS
010df073ccee   akrido-test   366.29%     27.06MiB / 7.673GiB   0.34%     456kB / 229kB   127kB / 0B   9

So I have some gut feeling that the resource_error(stack) is a misinterpretation of some other unexpected error. Unfortunately I have no concrete idea, how I could get somewhat closer to the root cause.

Kind regards,
Wolframo

11

Can you run outside the container? That would allow using more tooling, both Prolog (GUI) tooling as well as e.g., gdb. I expect the stack overflow to be real. Just, what is trapping it? A gdb breakpoint will tell us. It would also tell us how many threads are around at the moment things go wrong.

200 threads should be fine, though pretty useless if you do not have a similar number of cores.

12

Can you run outside the container?

I can reproduce a similar behaviour locally only when I reduce the stack limit after loading my grammar (which needs around 900K) to 200K and then running the test with the 100 parallelized 20-line-requests.

But this is expected behaviour. Whereas in the docker container I get those stack overflows with setting stack_limit to 1M, 1G, 4G - this does not seem to matter. I also tried swipl:latest instead of swipl:stable - got the same issue.

So my temporary assumption is that the issue somehow appears in the combination with call_with_inference_limit, the debian glibc used within the swipl image, cgroups…?

My local glibc says:

$ ldd --version
ldd (Ubuntu GLIBC 2.31-0ubuntu9.18) 2.31

on another computer I tried with glibc 2.35 - works fine, as expected.

Inside the docker is:

$ docker exec -it 1a59c7efaebd ldd --version
ldd (Debian GLIBC 2.36-9+deb12u14) 2.36

Not sure if glibc 2.36 could cause some issue in the specific situation. I might build my image from Ubuntu+swipl and than test again.

Kind regards,
Wolfram.

13

Trying with an Ubuntu image was helpful: It uses swipl 9.0.4 and with this I get an error on every request:

{
  "code":503,
  "message":"Service unavailable: error(resource_error(stack),stack_overflow{choicepoints:76,cycle:\[frame(2396392,vorto_gra:n_sup(\[1\],\[1\]),\[\]),frame(2396391,vorto_gra:n_sup(\[1\],\[1\]),\[\])\],depth:2396392,environments:2396378,globalused:112369,localused:262123,stack_limit:512000,trailused:5})"
}

This explains the stack error, but I have to investigate why it happens only with the docker build application. And also, why I get only occasional errors with Swipl 10.0.2. I will repost when I understand this better.

Regards,
Wolfram.

14

All seems a bit unlikely to me. Inference limit testing has no OS dependencies. I’m not sure it is somewhere heavily used to claim exhaustive testing though. I would be very surprised if glibc matters. cgroups? Well, possibly resource limits? Otherwise one would expect existence or permission issues.

I never experienced issues with Docker that do not reproduce outside Docker. If you can enable strace support inside the docker you may try strace to check for system call failures. I think the same support enables connecting gdb inside the container. That may also give some ideas.

15

after fixing the locale to a reasonable UTF-8 setup, it runs fine in Docker with ubuntu:noble image:

$ docker exec -it akrido-test ldd --version
ldd (Ubuntu GLIBC 2.39-0ubuntu8.7) 2.39

$ docker exec -it akrido-test swipl --version
SWI-Prolog version 9.0.4 for x86_64-linux

So the issue seems only happening in a non-deterministic way within the debian image (so some thread safety / race condition issue or so). E.g. I cannot reproduce it, if I load the service pl file and call the analyzing predicate within the REPL a few times.

I do not have a Debian installation here, so this would also explain that I could not reproduce the error locally.

So now I see two options:

  1. Try it within a Debian VM
  2. Or try to debug within the Debian container

There passed some decades since I used gdb last time, but I could try to remember how to debug C code properly… Will be quite difficult as in order to get the failure some concurrency and stochastic condition is required.

Kind regards,
Wolfram.

16

You can also change the locale in Debian. It is probably enough to use

 :- set_prolog_flag(encoding, utf8).

As first directive.

Unless you rely on some predicates that are locale sensitive, such as code_type/2 and format/1, that should be enough.

P.s. One would expect some warning during loading the files or execution …

17

Hi Jan,

I think I solved it: Something after the analysis part seems to have caused backtracking from time to time.
This could be the (concurrent_)maplist iteration itself or may be also reply_json(?) Mostlikely something related to concurrent use of a common resource.

analinioj(Request) :-
    http_read_json(Request, json(JSON)),
  ...
    concurrent_maplist(analizu_linion(Mode),Lines,Rezultoj),
    exclude(malplena,Rezultoj,Nemalplenaj),
    reply_json(json(Nemalplenaj)).

So adding a cut after a particular analysis call made the issue go away. I will observe it during next time, but some test runs look promising.

Thank you for your guidance,
kind regards,
Wolfram.

18

Unfortunately, the error is not gone, just less frequent now. Also replacing concurrent_maplist by simple maplist did not improve.

Using strace inside the container during test the only EM* / EN* errors I found were:
ENOTTY (Inappropriate ioctl for device) - I think I can ignore these…

Seems, I need more time to think about other possible causes.

Kind regards,
Wolfram.

19

Yes. It just tests whether a new stream is connected to a terminal or not.

The fact that the locale seems to have al least some impact might be a clue. We have also seen a possible cycle in the stack overflow. I would attach gdb to the process and put a breakpoint on outOfStack(). Note that you can use scripts/gdbinit as your .gdbinit, which provides some handy gdb settings and commands to make debugging Prolog easier. You may want to rebuild SWI-Prolog with debugging enabled. If the problem persists with that setting low level debugging is easier.

20

The out of stack seems to come from the garbage collection:

Thread 1217 "httpd@8081_2" hit Breakpoint 1, outOfStack (stack=0x55aaa84bb0a0, how=how@entry=STACK_OVERFLOW_RAISE) at /tmp/src/swipl-10.0.2/src/pl-alloc.c:670

670 /tmp/src/swipl-10.0.2/src/pl-alloc.c: No such file or directory.
(gdb) bt
#0  outOfStack (stack=0x55aaa84bb0a0, how=how@entry=STACK_OVERFLOW_RAISE) at /tmp/src/swipl-10.0.2/src/pl-alloc.c:670
#1  0x00007f94ead489f1 in raiseStackOverflow (overflow=<optimized out>) at /tmp/src/swipl-10.0.2/src/pl-alloc.c:762
#2  0x00007f94ead2dacc in ensureStackSpace_ex___LD (\__PL_ld=\__PL_ld@entry=0x55aaa84bb000, gcells=gcells@entry=4, flags=flags@entry=0, tcells=0) at /tmp/src/swipl-10.0.2/src/pl-gc.h:130
#3  0x00007f94ead2d47e in globalMPZ___LD (\__PL_ld=\__PL_ld@entry=0x55aaa84bb000, at=at@entry=0x7f94e12a0930, mpz=mpz@entry=0x7f94e12a08e0, flags=flags@entry=0) at /tmp/src/swipl-10.0.2/src/pl-gmp.c:496
#4  0x00007f94eadc6b39 in put_int64___LD (\__PL_ld=\__PL_ld@entry=0x55aaa84bb000, at=at@entry=0x7f94e12a0930, l=l@entry=9223372036854775807, flags=flags@entry=0) at /tmp/src/swipl-10.0.2/src/pl-gmp.c:1434
#5  0x00007f94ead4d82c in unify_int64_ex___LD (\__PL_ld=0x55aaa84bb000, t=483, i=9223372036854775807, ex=<optimized out>) at /tmp/src/swipl-10.0.2/src/pl-fli.c:3429
#6  0x00007f94eacfab6c in pl_pl_inference_limit2_va (PL__t0=482, PL__ac=<optimized out>, PL__ctx=<optimized out>) at /tmp/src/swipl-10.0.2/src/pl-prims.c:5517
#7  0x00007f94ead78c81 in PL_next_solution_guarded___LD (\__PL_ld=\__PL_ld@entry=0x55aaa84bb000, qid=qid@entry=0x55aaa811bd40, except=except@entry=false) at /tmp/src/swipl-10.0.2/src/pl-vmi.c:4343
#8  0x00007f94ead77416 in PL_next_solution___LD (\__PL_ld=\__PL_ld@entry=0x55aaa84bb000, qid=qid@entry=0x55aaa811bd40) at /tmp/src/swipl-10.0.2/src/pl-wam.c:3573
#9  0x00007f94ead90d2a in callProlog (module=<optimized out>, goal=goal@entry=21, flags=flags@entry=8200, ex=ex@entry=0x7f94e12a2db0) at /tmp/src/swipl-10.0.2/src/pl-pro.c:529
#10 0x00007f94ead216c1 in start_thread (closure=0x55aaa8398cc0) at /tmp/src/swipl-10.0.2/src/pl-thread.c:2156
#11 0x00007f94eab491f5 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#12 0x00007f94eabc8b50 in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:100

You may want to rebuild SWI-Prolog > with debugging enabled. If the problem persists with that setting low level debugging is easier.

Not sure about this: my Ubuntu 20.04 is too old for connecting gdb from the host system. I installed gdb inside the container though. Seems than the only option to add debug symbols would be to rebuild the Debian image with debugging enabled, am I right?

Regards,
Wolfram.