search

stef / ngx_http_auth_sasl_module

SASL authentication module for nginx
Other
3 stars 2 forks source link

Difficulty running `http_sasl.py` test script #1

Open leungbk opened 2 years ago

leungbk commented 2 years ago

I am able to build it successfully on both NixOS and Debian (the latter via Docker). In the Docker container, I am having an issue with the https://github.com/stef/libopaque/blob/master/sasl/http_sasl.py test script:

python3 ../libopaque/sasl/http_sasl.py
www-authenticate: SASL realm="localhost",mech="OPAQUE"
{'Authorization': 'SASL c2s="VHvCBFQYJ/iPzGM+qDoUlfVn5icAur4/CNCe0mayWydquhDeCw68YBwvBAGKSLPxMmQQ6sqEurlRMeu/cbvO2MgGHMrGYJKmAs/ku/QvWgP/d61KfOV5uUyDYRDY1xpQcwBzAA==",realm="localhost",mech="OPAQUE"'}
response status: 401
www-authenticate: None
Traceback (most recent call last):
  File "/Projects/ngx_http_auth_sasl_module/../libopaque/sasl/http_sasl.py", line 36, in <module>
    if not www_auth.startswith("SASL "):
AttributeError: 'NoneType' object has no attribute 'startswith'
make: *** [Makefile:45: curl] Error 1

Repro:

FROM debian:11

ENV DOCKER_NAME="debian-11"
ENV LANG C.UTF-8

RUN set -eux; \
        export DEBIAN_FRONTEND=noninteractive; \
        apt-get update; \
        apt-get install -y --no-install-recommends \
                apt-utils; \
        apt-get -y upgrade; \
        apt-get install -y --no-install-recommends \
                python3 \
                libsodium-dev \
                pkgconf \
                gcc \
                procps \
                curl \
                build-essential \
                zlib1g \
                zlib1g-dev \
                libpcre3 \
                libpcre3-dev \
                openssl \
                libsasl2-2 \
                libsasl2-dev \
                libsasl2-modules \
                libsasl2-modules-db \
                wget \
                tar \
                less \
                git \
                ca-certificates p11-kit; \
        rm -rf /var/lib/apt/lists/*; \
  1. Build and run a Docker container from the above Dockerfile.

Within the container,

  1. git submodule update --init --recursive --remote within the libopaque directory, make clean && make install within the libopaque/src directory, and make clean && make libopaque.so and cp libopaque.so /usr/lib/x86_64-linux-gnu/sasl2/ within the libopaque/sasl directory.
  2. make clean && make configure && make build within the ngx_http_auth_sasl_module directory.
  3. apt update && apt install -y python3-pip, then pip install requests sasl (Apparently, I get a different outcome if I install python-sasl before doing the libopaque/sasl step).
  4. Finally, make test within the ngx_http_auth_sasl_module directory.

I would appreciate some guidance on this, as it's the final hurdle for me to get this submitted to the Nix package repository.

stef commented 2 years ago

awesome! the problem is that libopaque is not found in the cyrus-sasl mech library directory. you need to copy it there. something like this:

sudo cp libopaque.so /usr/lib/sasl2

important, this is the libopaque from the sasl subdir, not from the src subdir (which also needs to be in place already.

stef commented 2 years ago

to explain: in line 24 of that script it says:

ret, mech, response = client.start('OPAQUE')

and client is a SASL client, and SASL mechs are identified by their canonical name, in this case OPAQUE. All mech libraries are read upon start of the main SASL library and each mech registers itself with it's canonical name, so that later clients and servers can just ask give me a client that can do this-or-that mechanism. so there's an indirection which hides the fact it tries to load the libopaque.so lib.

in my system the mechs in /usr/lib/sasl2 are libs like libanonymous.so or libplain.so...

leungbk commented 2 years ago

Thanks for the quick response. Your explanation makes sense. I've gotten a bit farther along, but am now encountering a different issue (I've updated my reproduction steps accordingly).

After making sure to install python-sasl only after doing the libopaque.so steps (not sure why order matters), and confirming that the SASL libopaque.so is being moved to the same directory, /usr/lib/x86_64-linux-gnu/sasl2/, as the other libanonymous.so libraries, I now encounter the following error:

python3 ../libopaque/sasl/http_sasl.py
www-authenticate: SASL realm="localhost",mech="OPAQUE"
{'Authorization': 'SASL c2s="VHvCBFQYJ/iPzGM+qDoUlfVn5icAur4/CNCe0mayWydquhDeCw68YBwvBAGKSLPxMmQQ6sqEurlRMeu/cbvO2MgGHMrGYJKmAs/ku/QvWgP/d61KfOV5uUyDYRDY1xpQcwBzAA==",realm="localhost",mech="OPAQUE"'}
response status: 401
www-authenticate: None
Traceback (most recent call last):
  File "/Projects/ngx_http_auth_sasl_module/../libopaque/sasl/http_sasl.py", line 36, in <module>
    if not www_auth.startswith("SASL "):
AttributeError: 'NoneType' object has no attribute 'startswith'
make: *** [Makefile:45: curl] Error 1
stef commented 2 years ago

your webserver is not configured to require sasl auth for the requested resource. ~you should set up nginx with a config like this: https://github.com/stef/ngx_http_auth_sasl_module#config~ and also populate /usr/local/etc/sasldb2 with a user s and a password asdf as set in the script, something like this:

sudo rm /usr/local/etc/sasldb2 
sudo /usr/sbin/saslpasswd2 -n -f /usr/local/etc/sasldb2 -a sample -c -u localhost s && sudo chmod o+r /usr/local/etc/sasldb2
stef commented 2 years ago

ah, the nginx module comes with a config in debug.conf

stef commented 2 years ago

can you share the file root/logs/error.log please?

leungbk commented 2 years ago

I think we're making progress. After initializing the database as you describe, I now reach the final batch of prints in http_sasl.py with a client error:

python3 ../libopaque/sasl/http_sasl.py
www-authenticate: SASL realm="localhost",mech="OPAQUE"
{'Authorization': 'SASL c2s="oISf2AzuR4yNYxfLg3Le0IzGXxMpSyN8WiXip94oqzKEnjRleXGI4fUs9V5W2BRYVp7Ea8AphLW2zrGKFkmPCKhXCKrm5FZ90U0/RBAL3G0KGzWMIzxPCudH758/IgJycwBzAA==",realm="localhost",mech="OPAQUE"'}
response status: 401
www-authenticate: SASL s2c="aJFGNjNocFkYjCcBB90nKN5tnrGk8JUGF+5OuHquoE2nJ6Lda9Q9PH3Fle0GFs2eKb3X4mx3+jHda2GTdBGDyRxWE/I1STPv6zz7xcXWLZR8dwZpOtzUdBKTsUdrjSJ+LFcp5GASalio5st6JLI7X4ridlTPyVvG/lLB2HqGSy6gXmdL5df7pFTqDB0pjPZwIKNukGgOgRjgx3JXqZ48Jx+z1iVgjYUlRgw3PXKk6fTwL9skkHJWLRfEoT+/ksWHFVbLkibfxhoE/rfYG36gICAjv9uuz9O5faoXXvhFkYx6vxdU5jXCHkUDfkbY2jpNBM+FoogIV18/E5oah72gJH8puOjO+5uM9t3SxOV2IBolrAGrQa/0Wpf6s4tX7o7INLltWy3jSRd/jQmyTKjjlUFcPaEMCGIIhQXQSRr9k6Jsb2NhbGhvc3QA",s2s="0000000017DA543C"
{'Authorization': 'SASL c2s="NIJiFi+QkkzioCEU5WPtpOUK9GMfwriOhF5I1Uj+uMe6QgzuIJr4wD7ysV7kKCPrfzIlMQXSpTyZdmwWdRf9mw==",s2s="0000000017DA543C"'}
response status: 403
www-authenticate: SASL s2c="",s2s="0000000017DA543C"
<html>
<head><title>403 Forbidden</title></head>
<body>
<center><h1>403 Forbidden</h1></center>
<hr><center>nginx/1.23.1</center>
</body>
</html>

root/logs/error.log is:

2022/07/28 23:26:24 [debug] 3722#0: bind() 0.0.0.0:8090 #6 
2022/07/28 23:26:24 [notice] 3722#0: using the "epoll" event method
2022/07/28 23:26:24 [debug] 3722#0: counter: 00007F1DE0D28080, 1
2022/07/28 23:26:24 [notice] 3722#0: nginx/1.23.1
2022/07/28 23:26:24 [notice] 3722#0: OS: Linux 5.18.13
2022/07/28 23:26:24 [notice] 3722#0: getrlimit(RLIMIT_NOFILE): 1048576:1048576
2022/07/28 23:26:24 [debug] 3723#0: write: 7, 00007FFEC7C62840, 5, 0
2022/07/28 23:26:24 [debug] 3723#0: setproctitle: "nginx: master process ../nginx/objs/nginx -p /Projects/ngx_http_auth_sasl_module/root -c debug.conf"
2022/07/28 23:26:24 [notice] 3723#0: start worker processes
2022/07/28 23:26:24 [debug] 3723#0: channel 3:7
2022/07/28 23:26:24 [notice] 3723#0: start worker process 3724
2022/07/28 23:26:24 [debug] 3723#0: sigsuspend
2022/07/28 23:26:24 [debug] 3724#0: add cleanup: 0000563722329758
2022/07/28 23:26:24 [debug] 3724#0: malloc: 0000563722317E80:8
2022/07/28 23:26:24 [debug] 3724#0: notify eventfd: 9
2022/07/28 23:26:24 [debug] 3724#0: testing the EPOLLRDHUP flag: success
2022/07/28 23:26:24 [debug] 3724#0: malloc: 000056372231C5D0:6144
2022/07/28 23:26:24 [debug] 3724#0: malloc: 0000563722339C40:114688
2022/07/28 23:26:24 [debug] 3724#0: malloc: 0000563722355C50:49152
2022/07/28 23:26:24 [debug] 3724#0: malloc: 0000563722361C60:49152
2022/07/28 23:26:24 [debug] 3724#0: epoll add event: fd:6 op:1 ev:00002001
2022/07/28 23:26:24 [debug] 3724#0: epoll add event: fd:7 op:1 ev:00002001
2022/07/28 23:26:24 [debug] 3724#0: setproctitle: "nginx: worker process"
2022/07/28 23:26:24 [debug] 3724#0: worker cycle
2022/07/28 23:26:24 [debug] 3724#0: epoll timer: -1
2022/07/28 23:26:24 [debug] 3724#0: epoll: fd:6 ev:0001 d:0000563722339C40
2022/07/28 23:26:24 [debug] 3724#0: accept on 0.0.0.0:8090, ready: 0
2022/07/28 23:26:24 [debug] 3724#0: posix_memalign: 0000563722317FF0:512 @16
2022/07/28 23:26:24 [debug] 3724#0: *1 accept: 127.0.0.1:57548 fd:3
2022/07/28 23:26:24 [debug] 3724#0: *1 event timer add: 3: 60000:31279337
2022/07/28 23:26:24 [debug] 3724#0: *1 reusable connection: 1
2022/07/28 23:26:24 [debug] 3724#0: *1 epoll add event: fd:3 op:1 ev:80002001
2022/07/28 23:26:24 [debug] 3724#0: timer delta: 73
2022/07/28 23:26:24 [debug] 3724#0: worker cycle
2022/07/28 23:26:24 [debug] 3724#0: epoll timer: 60000
2022/07/28 23:26:24 [debug] 3724#0: epoll: fd:3 ev:0001 d:0000563722339E00
2022/07/28 23:26:24 [debug] 3724#0: *1 http wait request handler
2022/07/28 23:26:24 [debug] 3724#0: *1 malloc: 000056372230E5C0:1024
2022/07/28 23:26:24 [debug] 3724#0: *1 recv: eof:0, avail:-1
2022/07/28 23:26:24 [debug] 3724#0: *1 recv: fd:3 145 of 1024
2022/07/28 23:26:24 [debug] 3724#0: *1 reusable connection: 0
2022/07/28 23:26:24 [debug] 3724#0: *1 posix_memalign: 000056372231DDE0:4096 @16
2022/07/28 23:26:24 [debug] 3724#0: *1 http process request line
2022/07/28 23:26:24 [debug] 3724#0: *1 http request line: "GET / HTTP/1.1"
2022/07/28 23:26:24 [debug] 3724#0: *1 http uri: "/"
2022/07/28 23:26:24 [debug] 3724#0: *1 http args: ""
2022/07/28 23:26:24 [debug] 3724#0: *1 http exten: ""
2022/07/28 23:26:24 [debug] 3724#0: *1 posix_memalign: 00005637223135A0:4096 @16
2022/07/28 23:26:24 [debug] 3724#0: *1 http process request header line
2022/07/28 23:26:24 [debug] 3724#0: *1 http header: "Host: localhost:8090"
2022/07/28 23:26:24 [debug] 3724#0: *1 http header: "User-Agent: python-requests/2.28.1"
2022/07/28 23:26:24 [debug] 3724#0: *1 http header: "Accept-Encoding: gzip, deflate"
2022/07/28 23:26:24 [debug] 3724#0: *1 http header: "Accept: */*"
2022/07/28 23:26:24 [debug] 3724#0: *1 http header: "Connection: keep-alive"
2022/07/28 23:26:24 [debug] 3724#0: *1 http header done
2022/07/28 23:26:24 [debug] 3724#0: *1 event timer del: 3: 31279337
2022/07/28 23:26:24 [debug] 3724#0: *1 rewrite phase: 0
2022/07/28 23:26:24 [debug] 3724#0: *1 using configuration ""
2022/07/28 23:26:24 [debug] 3724#0: *1 http cl:-1 max:1048576
2022/07/28 23:26:24 [debug] 3724#0: *1 rewrite phase: 2
2022/07/28 23:26:24 [debug] 3724#0: *1 post rewrite phase: 3
2022/07/28 23:26:24 [debug] 3724#0: *1 generic phase: 4
2022/07/28 23:26:24 [debug] 3724#0: *1 generic phase: 5
2022/07/28 23:26:24 [debug] 3724#0: *1 access phase: 6
2022/07/28 23:26:24 [debug] 3724#0: *1 SASL HANDLER
2022/07/28 23:26:24 [debug] 3724#0: *1 SASL HANDLER REALM: localhost
2022/07/28 23:26:24 [debug] 3724#0: *1 http finalize request: 401, "/?" a:1, c:1
2022/07/28 23:26:24 [debug] 3724#0: *1 http special response: 401, "/?"
2022/07/28 23:26:24 [debug] 3724#0: *1 http set discard body
2022/07/28 23:26:24 [debug] 3724#0: *1 HTTP/1.1 401 Unauthorized
Server: nginx/1.23.1
Date: Thu, 28 Jul 2022 23:26:24 GMT
Content-Type: text/html
Content-Length: 179
Connection: keep-alive
WWW-Authenticate: SASL realm="localhost",mech="OPAQUE"

2022/07/28 23:26:24 [debug] 3724#0: *1 write new buf t:1 f:0 000056372231EB78, pos 000056372231EB78, size: 214 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *1 http write filter: l:0 f:0 s:214
2022/07/28 23:26:24 [debug] 3724#0: *1 http output filter "/?"
2022/07/28 23:26:24 [debug] 3724#0: *1 http copy filter: "/?"
2022/07/28 23:26:24 [debug] 3724#0: *1 http postpone filter "/?" 000056372231ED78
2022/07/28 23:26:24 [debug] 3724#0: *1 write old buf t:1 f:0 000056372231EB78, pos 000056372231EB78, size: 214 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *1 write new buf t:0 f:0 0000000000000000, pos 0000563721D18620, size: 126 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *1 write new buf t:0 f:0 0000000000000000, pos 0000563721D18080, size: 53 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *1 http write filter: l:1 f:0 s:393
2022/07/28 23:26:24 [debug] 3724#0: *1 http write filter limit 2097152
2022/07/28 23:26:24 [debug] 3724#0: *1 writev: 393 of 393
2022/07/28 23:26:24 [debug] 3724#0: *1 http write filter 0000000000000000
2022/07/28 23:26:24 [debug] 3724#0: *1 http copy filter: 0 "/?"
2022/07/28 23:26:24 [debug] 3724#0: *1 http finalize request: 0, "/?" a:1, c:1
2022/07/28 23:26:24 [debug] 3724#0: *1 set http keepalive handler
2022/07/28 23:26:24 [debug] 3724#0: *1 http close request
2022/07/28 23:26:24 [debug] 3724#0: *1 http log handler
2022/07/28 23:26:24 [debug] 3724#0: *1 free: 000056372231DDE0, unused: 40
2022/07/28 23:26:24 [debug] 3724#0: *1 free: 00005637223135A0, unused: 2813
2022/07/28 23:26:24 [debug] 3724#0: *1 free: 000056372230E5C0
2022/07/28 23:26:24 [debug] 3724#0: *1 hc free: 0000000000000000
2022/07/28 23:26:24 [debug] 3724#0: *1 hc busy: 0000000000000000 0
2022/07/28 23:26:24 [debug] 3724#0: *1 tcp_nodelay
2022/07/28 23:26:24 [debug] 3724#0: *1 reusable connection: 1
2022/07/28 23:26:24 [debug] 3724#0: *1 event timer add: 3: 75000:31294342
2022/07/28 23:26:24 [debug] 3724#0: timer delta: 5
2022/07/28 23:26:24 [debug] 3724#0: worker cycle
2022/07/28 23:26:24 [debug] 3724#0: epoll timer: 75000
2022/07/28 23:26:24 [debug] 3724#0: epoll: fd:3 ev:2001 d:0000563722339E00
2022/07/28 23:26:24 [debug] 3724#0: *1 http keepalive handler
2022/07/28 23:26:24 [debug] 3724#0: *1 malloc: 000056372230E5C0:1024
2022/07/28 23:26:24 [debug] 3724#0: *1 recv: eof:1, avail:-1
2022/07/28 23:26:24 [debug] 3724#0: *1 recv: fd:3 0 of 1024
2022/07/28 23:26:24 [info] 3724#0: *1 client 127.0.0.1 closed keepalive connection
2022/07/28 23:26:24 [debug] 3724#0: *1 close http connection: 3
2022/07/28 23:26:24 [debug] 3724#0: *1 event timer del: 3: 31294342
2022/07/28 23:26:24 [debug] 3724#0: *1 reusable connection: 0
2022/07/28 23:26:24 [debug] 3724#0: *1 free: 000056372230E5C0
2022/07/28 23:26:24 [debug] 3724#0: *1 free: 0000563722317FF0, unused: 152
2022/07/28 23:26:24 [debug] 3724#0: timer delta: 13
2022/07/28 23:26:24 [debug] 3724#0: worker cycle
2022/07/28 23:26:24 [debug] 3724#0: epoll timer: -1
2022/07/28 23:26:24 [debug] 3724#0: epoll: fd:6 ev:0001 d:0000563722339C40
2022/07/28 23:26:24 [debug] 3724#0: accept on 0.0.0.0:8090, ready: 0
2022/07/28 23:26:24 [debug] 3724#0: posix_memalign: 0000563722317FF0:512 @16
2022/07/28 23:26:24 [debug] 3724#0: *2 accept: 127.0.0.1:57556 fd:3
2022/07/28 23:26:24 [debug] 3724#0: *2 event timer add: 3: 60000:31279357
2022/07/28 23:26:24 [debug] 3724#0: *2 reusable connection: 1
2022/07/28 23:26:24 [debug] 3724#0: *2 epoll add event: fd:3 op:1 ev:80002001
2022/07/28 23:26:24 [debug] 3724#0: timer delta: 2
2022/07/28 23:26:24 [debug] 3724#0: worker cycle
2022/07/28 23:26:24 [debug] 3724#0: epoll timer: 60000
2022/07/28 23:26:24 [debug] 3724#0: epoll: fd:3 ev:0001 d:0000563722339E01
2022/07/28 23:26:24 [debug] 3724#0: *2 http wait request handler
2022/07/28 23:26:24 [debug] 3724#0: *2 malloc: 000056372230E5C0:1024
2022/07/28 23:26:24 [debug] 3724#0: *2 recv: eof:0, avail:-1
2022/07/28 23:26:24 [debug] 3724#0: *2 recv: fd:3 341 of 1024
2022/07/28 23:26:24 [debug] 3724#0: *2 reusable connection: 0
2022/07/28 23:26:24 [debug] 3724#0: *2 posix_memalign: 000056372231DDE0:4096 @16
2022/07/28 23:26:24 [debug] 3724#0: *2 http process request line
2022/07/28 23:26:24 [debug] 3724#0: *2 http request line: "GET / HTTP/1.1"
2022/07/28 23:26:24 [debug] 3724#0: *2 http uri: "/"
2022/07/28 23:26:24 [debug] 3724#0: *2 http args: ""
2022/07/28 23:26:24 [debug] 3724#0: *2 http exten: ""
2022/07/28 23:26:24 [debug] 3724#0: *2 posix_memalign: 00005637223135A0:4096 @16
2022/07/28 23:26:24 [debug] 3724#0: *2 http process request header line
2022/07/28 23:26:24 [debug] 3724#0: *2 http header: "Host: localhost:8090"
2022/07/28 23:26:24 [debug] 3724#0: *2 http header: "User-Agent: python-requests/2.28.1"
2022/07/28 23:26:24 [debug] 3724#0: *2 http header: "Accept-Encoding: gzip, deflate"
2022/07/28 23:26:24 [debug] 3724#0: *2 http header: "Accept: */*"
2022/07/28 23:26:24 [debug] 3724#0: *2 http header: "Connection: keep-alive"
2022/07/28 23:26:24 [debug] 3724#0: *2 http header: "Authorization: SASL c2s="oISf2AzuR4yNYxfLg3Le0IzGXxMpSyN8WiXip94oqzKEnjRleXGI4fUs9V5W2BRYVp7Ea8AphLW2zrGKFkmPCKhXCKrm5FZ90U0/RBAL3G0KGzWMIzxPCudH758/IgJycwBzAA==",realm="localhost",mech="OPAQUE""
2022/07/28 23:26:24 [debug] 3724#0: *2 http header done
2022/07/28 23:26:24 [debug] 3724#0: *2 event timer del: 3: 31279357
2022/07/28 23:26:24 [debug] 3724#0: *2 rewrite phase: 0
2022/07/28 23:26:24 [debug] 3724#0: *2 using configuration ""
2022/07/28 23:26:24 [debug] 3724#0: *2 http cl:-1 max:1048576
2022/07/28 23:26:24 [debug] 3724#0: *2 rewrite phase: 2
2022/07/28 23:26:24 [debug] 3724#0: *2 post rewrite phase: 3
2022/07/28 23:26:24 [debug] 3724#0: *2 generic phase: 4
2022/07/28 23:26:24 [debug] 3724#0: *2 generic phase: 5
2022/07/28 23:26:24 [debug] 3724#0: *2 access phase: 6
2022/07/28 23:26:24 [debug] 3724#0: *2 SASL HANDLER
2022/07/28 23:26:24 [debug] 3724#0: *2 SASL HANDLER REALM: localhost
2022/07/28 23:26:24 [debug] 3724#0: *2 Authorize Header: SASL c2s="oISf2AzuR4yNYxfLg3Le0IzGXxMpSyN8WiXip94oqzKEnjRleXGI4fUs9V5W2BRYVp7Ea8AphLW2zrGKFkmPCKhXCKrm5FZ90U0/RBAL3G0KGzWMIzxPCudH758/IgJycwBzAA==",realm="localhost",mech="OPAQUE"
2022/07/28 23:26:24 [debug] 3724#0: *2 decoded c2s
2022/07/28 23:26:24 [debug] 3724#0: *2 new sasl_server: 0
2022/07/28 23:26:24 [debug] 3724#0: *2 starting sasl_server: 1
2022/07/28 23:26:24 [debug] 3724#0: *2 sasl header set
2022/07/28 23:26:24 [debug] 3724#0: *2 sasl returning 401
2022/07/28 23:26:24 [debug] 3724#0: *2 http finalize request: 401, "/?" a:1, c:1
2022/07/28 23:26:24 [debug] 3724#0: *2 http special response: 401, "/?"
2022/07/28 23:26:24 [debug] 3724#0: *2 http set discard body
2022/07/28 23:26:24 [debug] 3724#0: *2 HTTP/1.1 401 Unauthorized
Server: nginx/1.23.1
Date: Thu, 28 Jul 2022 23:26:24 GMT
Content-Type: text/html
Content-Length: 179
Connection: keep-alive
WWW-Authenticate: SASL s2c="aJFGNjNocFkYjCcBB90nKN5tnrGk8JUGF+5OuHquoE2nJ6Lda9Q9PH3Fle0GFs2eKb3X4mx3+jHda2GTdBGDyRxWE/I1STPv6zz7xcXWLZR8dwZpOtzUdBKTsUdrjSJ+LFcp5GASalio5st6JLI7X4ridlTPyVvG/lLB2HqGSy6gXmdL5df7pFTqDB0pjPZwIKNukGgOgRjgx3JXqZ48Jx+z1iVgjYUlRgw3PXKk6fTwL9skkHJWLRfEoT+/ksWHFVbLkibfxhoE/rfYG36gICAjv9uuz9O5faoXXvhFkYx6vxdU5jXCHkUDfkbY2jpNBM+FoogIV18/E5oah72gJH8puOjO+5uM9t3SxOV2IBolrAGrQa/0Wpf6s4tX7o7INLltWy3jSRd/jQmyTKjjlUFcPaEMCGIIhQXQSRr9k6Jsb2NhbGhvc3QA",s2s="0000000017DA543C"

2022/07/28 23:26:24 [debug] 3724#0: *2 write new buf t:1 f:0 0000563722313A20, pos 0000563722313A20, size: 652 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *2 http write filter: l:0 f:0 s:652
2022/07/28 23:26:24 [debug] 3724#0: *2 http output filter "/?"
2022/07/28 23:26:24 [debug] 3724#0: *2 http copy filter: "/?"
2022/07/28 23:26:24 [debug] 3724#0: *2 http postpone filter "/?" 000056372231EDA0
2022/07/28 23:26:24 [debug] 3724#0: *2 write old buf t:1 f:0 0000563722313A20, pos 0000563722313A20, size: 652 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *2 write new buf t:0 f:0 0000000000000000, pos 0000563721D18620, size: 126 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *2 write new buf t:0 f:0 0000000000000000, pos 0000563721D18080, size: 53 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *2 http write filter: l:1 f:0 s:831
2022/07/28 23:26:24 [debug] 3724#0: *2 http write filter limit 2097152
2022/07/28 23:26:24 [debug] 3724#0: *2 writev: 831 of 831
2022/07/28 23:26:24 [debug] 3724#0: *2 http write filter 0000000000000000
2022/07/28 23:26:24 [debug] 3724#0: *2 http copy filter: 0 "/?"
2022/07/28 23:26:24 [debug] 3724#0: *2 http finalize request: 0, "/?" a:1, c:1
2022/07/28 23:26:24 [debug] 3724#0: *2 set http keepalive handler
2022/07/28 23:26:24 [debug] 3724#0: *2 http close request
2022/07/28 23:26:24 [debug] 3724#0: *2 http log handler
2022/07/28 23:26:24 [debug] 3724#0: *2 free: 000056372231DDE0, unused: 0
2022/07/28 23:26:24 [debug] 3724#0: *2 free: 00005637223135A0, unused: 1957
2022/07/28 23:26:24 [debug] 3724#0: *2 free: 000056372230E5C0
2022/07/28 23:26:24 [debug] 3724#0: *2 hc free: 0000000000000000
2022/07/28 23:26:24 [debug] 3724#0: *2 hc busy: 0000000000000000 0
2022/07/28 23:26:24 [debug] 3724#0: *2 tcp_nodelay
2022/07/28 23:26:24 [debug] 3724#0: *2 reusable connection: 1
2022/07/28 23:26:24 [debug] 3724#0: *2 event timer add: 3: 75000:31294357
2022/07/28 23:26:24 [debug] 3724#0: timer delta: 0
2022/07/28 23:26:24 [debug] 3724#0: worker cycle
2022/07/28 23:26:24 [debug] 3724#0: epoll timer: 75000
2022/07/28 23:26:24 [debug] 3724#0: epoll: fd:3 ev:2001 d:0000563722339E01
2022/07/28 23:26:24 [debug] 3724#0: *2 http keepalive handler
2022/07/28 23:26:24 [debug] 3724#0: *2 malloc: 000056372230E5C0:1024
2022/07/28 23:26:24 [debug] 3724#0: *2 recv: eof:1, avail:-1
2022/07/28 23:26:24 [debug] 3724#0: *2 recv: fd:3 0 of 1024
2022/07/28 23:26:24 [info] 3724#0: *2 client 127.0.0.1 closed keepalive connection
2022/07/28 23:26:24 [debug] 3724#0: *2 close http connection: 3
2022/07/28 23:26:24 [debug] 3724#0: *2 event timer del: 3: 31294357
2022/07/28 23:26:24 [debug] 3724#0: *2 reusable connection: 0
2022/07/28 23:26:24 [debug] 3724#0: *2 free: 000056372230E5C0
2022/07/28 23:26:24 [debug] 3724#0: *2 free: 0000563722317FF0, unused: 152
2022/07/28 23:26:24 [debug] 3724#0: timer delta: 11
2022/07/28 23:26:24 [debug] 3724#0: worker cycle
2022/07/28 23:26:24 [debug] 3724#0: epoll timer: -1
2022/07/28 23:26:24 [debug] 3724#0: epoll: fd:6 ev:0001 d:0000563722339C40
2022/07/28 23:26:24 [debug] 3724#0: accept on 0.0.0.0:8090, ready: 0
2022/07/28 23:26:24 [debug] 3724#0: posix_memalign: 0000563722317FF0:512 @16
2022/07/28 23:26:24 [debug] 3724#0: *3 accept: 127.0.0.1:57558 fd:3
2022/07/28 23:26:24 [debug] 3724#0: *3 event timer add: 3: 60000:31279444
2022/07/28 23:26:24 [debug] 3724#0: *3 reusable connection: 1
2022/07/28 23:26:24 [debug] 3724#0: *3 epoll add event: fd:3 op:1 ev:80002001
2022/07/28 23:26:24 [debug] 3724#0: timer delta: 76
2022/07/28 23:26:24 [debug] 3724#0: worker cycle
2022/07/28 23:26:24 [debug] 3724#0: epoll timer: 60000
2022/07/28 23:26:24 [debug] 3724#0: epoll: fd:3 ev:0001 d:0000563722339E00
2022/07/28 23:26:24 [debug] 3724#0: *3 http wait request handler
2022/07/28 23:26:24 [debug] 3724#0: *3 malloc: 000056372230E5C0:1024
2022/07/28 23:26:24 [debug] 3724#0: *3 recv: eof:0, avail:-1
2022/07/28 23:26:24 [debug] 3724#0: *3 recv: fd:3 284 of 1024
2022/07/28 23:26:24 [debug] 3724#0: *3 reusable connection: 0
2022/07/28 23:26:24 [debug] 3724#0: *3 posix_memalign: 000056372231DDE0:4096 @16
2022/07/28 23:26:24 [debug] 3724#0: *3 http process request line
2022/07/28 23:26:24 [debug] 3724#0: *3 http request line: "GET / HTTP/1.1"
2022/07/28 23:26:24 [debug] 3724#0: *3 http uri: "/"
2022/07/28 23:26:24 [debug] 3724#0: *3 http args: ""
2022/07/28 23:26:24 [debug] 3724#0: *3 http exten: ""
2022/07/28 23:26:24 [debug] 3724#0: *3 posix_memalign: 00005637223135A0:4096 @16
2022/07/28 23:26:24 [debug] 3724#0: *3 http process request header line
2022/07/28 23:26:24 [debug] 3724#0: *3 http header: "Host: localhost:8090"
2022/07/28 23:26:24 [debug] 3724#0: *3 http header: "User-Agent: python-requests/2.28.1"
2022/07/28 23:26:24 [debug] 3724#0: *3 http header: "Accept-Encoding: gzip, deflate"
2022/07/28 23:26:24 [debug] 3724#0: *3 http header: "Accept: */*"
2022/07/28 23:26:24 [debug] 3724#0: *3 http header: "Connection: keep-alive"
2022/07/28 23:26:24 [debug] 3724#0: *3 http header: "Authorization: SASL c2s="NIJiFi+QkkzioCEU5WPtpOUK9GMfwriOhF5I1Uj+uMe6QgzuIJr4wD7ysV7kKCPrfzIlMQXSpTyZdmwWdRf9mw==",s2s="0000000017DA543C""
2022/07/28 23:26:24 [debug] 3724#0: *3 http header done
2022/07/28 23:26:24 [debug] 3724#0: *3 event timer del: 3: 31279444
2022/07/28 23:26:24 [debug] 3724#0: *3 rewrite phase: 0
2022/07/28 23:26:24 [debug] 3724#0: *3 using configuration ""
2022/07/28 23:26:24 [debug] 3724#0: *3 http cl:-1 max:1048576
2022/07/28 23:26:24 [debug] 3724#0: *3 rewrite phase: 2
2022/07/28 23:26:24 [debug] 3724#0: *3 post rewrite phase: 3
2022/07/28 23:26:24 [debug] 3724#0: *3 generic phase: 4
2022/07/28 23:26:24 [debug] 3724#0: *3 generic phase: 5
2022/07/28 23:26:24 [debug] 3724#0: *3 access phase: 6
2022/07/28 23:26:24 [debug] 3724#0: *3 SASL HANDLER
2022/07/28 23:26:24 [debug] 3724#0: *3 SASL HANDLER REALM: localhost
2022/07/28 23:26:24 [debug] 3724#0: *3 Authorize Header: SASL c2s="NIJiFi+QkkzioCEU5WPtpOUK9GMfwriOhF5I1Uj+uMe6QgzuIJr4wD7ysV7kKCPrfzIlMQXSpTyZdmwWdRf9mw==",s2s="0000000017DA543C"
2022/07/28 23:26:24 [debug] 3724#0: *3 decoded c2s
2022/07/28 23:26:24 [debug] 3724#0: *3 loading sasl_server
2022/07/28 23:26:24 [debug] 3724#0: *3 stepping sasl_server: 0
2022/07/28 23:26:24 [debug] 3724#0: *3 sasl header set
2022/07/28 23:26:24 [debug] 3724#0: *3 sasl_ok
2022/07/28 23:26:24 [debug] 3724#0: *3 setting variable idx(2): s@localhostE2nJ6Lda9Q9PH3Fle0GFs2eKb3X4mx3+jHda2GTdBGDyRxWE/I1STPv6zz7xcXWLZR8dwZpOtzUdBKTsUdrjSJ+LFcp5GASalio5st6JLI7X4ridlTPyVvG/lLB2HqGSy6gXmdL5df7pFTqDB0pjPZwIKNukGgOgRjgx3JXqZ48Jx+z1iVgjYUlRgw3PXKk6fTwL9skkHJWLRfEoT+/ksWHFVbLkibfxhoE/rfYG36gICAjv9uuz9O5faoXXvhFkYx6vxdU5jXCHkUDfkbY2jpNBM+FoogIV18/E5oah72gJH8puOjO+5uM9t3SxOV2IBolrAGrQa/0Wpf6s4tX7o7INLltWy3jSRd/jQmyTKjjlUFcPaEMCGIIhQXQSRr9k6Jsb2NhbGhvc3QA",s2s="0000000017DA543C"
2022/07/28 23:26:24 [debug] 3724#0: *3 setting variable idx(0): yes
2022/07/28 23:26:24 [debug] 3724#0: *3 setting variable idx(1): OPAQUEPH3Fle0GFs2eKb3X4mx3+jHda2GTdBGDyRxWE/I1STPv6zz7xcXWLZR8dwZpOtzUdBKTsUdrjSJ+LFcp5GASalio5st6JLI7X4ridlTPyVvG/lLB2HqGSy6gXmdL5df7pFTqDB0pjPZwIKNukGgOgRjgx3JXqZ48Jx+z1iVgjYUlRgw3PXKk6fTwL9skkHJWLRfEoT+/ksWHFVbLkibfxhoE/rfYG36gICAjv9uuz9O5faoXXvhFkYx6vxdU5jXCHkUDfkbY2jpNBM+FoogIV18/E5oah72gJH8puOjO+5uM9t3SxOV2IBolrAGrQa/0Wpf6s4tX7o7INLltWy3jSRd/jQmyTKjjlUFcPaEMCGIIhQXQSRr9k6Jsb2NhbGhvc3QA",s2s="0000000017DA543C"
2022/07/28 23:26:24 [debug] 3724#0: *3 access phase: 7
2022/07/28 23:26:24 [debug] 3724#0: *3 access phase: 8
2022/07/28 23:26:24 [debug] 3724#0: *3 post access phase: 9
2022/07/28 23:26:24 [debug] 3724#0: *3 generic phase: 10
2022/07/28 23:26:24 [debug] 3724#0: *3 generic phase: 11
2022/07/28 23:26:24 [debug] 3724#0: *3 content phase: 12
2022/07/28 23:26:24 [debug] 3724#0: *3 open index "/Projects/ngx_http_auth_sasl_module/root/./index.html"
2022/07/28 23:26:24 [debug] 3724#0: *3 stat() "/Projects/ngx_http_auth_sasl_module/root/./index.html" failed (2: No such file or directory)
2022/07/28 23:26:24 [debug] 3724#0: *3 http index check dir: "/Projects/ngx_http_auth_sasl_module/root/."
2022/07/28 23:26:24 [debug] 3724#0: *3 content phase: 13
2022/07/28 23:26:24 [debug] 3724#0: *3 content phase: 14
2022/07/28 23:26:24 [error] 3724#0: *3 directory index of "/Projects/ngx_http_auth_sasl_module/root/./" is forbidden, client: 127.0.0.1, server: , request: "GET / HTTP/1.1", host: "localhost:8090"
2022/07/28 23:26:24 [debug] 3724#0: *3 http finalize request: 403, "/?" a:1, c:1
2022/07/28 23:26:24 [debug] 3724#0: *3 http special response: 403, "/?"
2022/07/28 23:26:24 [debug] 3724#0: *3 http set discard body
2022/07/28 23:26:24 [debug] 3724#0: *3 HTTP/1.1 403 Forbidden
Server: nginx/1.23.1
Date: Thu, 28 Jul 2022 23:26:24 GMT
Content-Type: text/html
Content-Length: 153
Connection: keep-alive
WWW-Authenticate: SASL s2c="",s2s="0000000017DA543C"

2022/07/28 23:26:24 [debug] 3724#0: *3 write new buf t:1 f:0 000056372231EC08, pos 000056372231EC08, size: 209 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *3 http write filter: l:0 f:0 s:209
2022/07/28 23:26:24 [debug] 3724#0: *3 http output filter "/?"
2022/07/28 23:26:24 [debug] 3724#0: *3 http copy filter: "/?"
2022/07/28 23:26:24 [debug] 3724#0: *3 http postpone filter "/?" 000056372231EDA0
2022/07/28 23:26:24 [debug] 3724#0: *3 write old buf t:1 f:0 000056372231EC08, pos 000056372231EC08, size: 209 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *3 write new buf t:0 f:0 0000000000000000, pos 0000563721D18720, size: 100 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *3 write new buf t:0 f:0 0000000000000000, pos 0000563721D18080, size: 53 file: 0, size: 0
2022/07/28 23:26:24 [debug] 3724#0: *3 http write filter: l:1 f:0 s:362
2022/07/28 23:26:24 [debug] 3724#0: *3 http write filter limit 2097152
2022/07/28 23:26:24 [debug] 3724#0: *3 writev: 362 of 362
2022/07/28 23:26:24 [debug] 3724#0: *3 http write filter 0000000000000000
2022/07/28 23:26:24 [debug] 3724#0: *3 http copy filter: 0 "/?"
2022/07/28 23:26:24 [debug] 3724#0: *3 http finalize request: 0, "/?" a:1, c:1
2022/07/28 23:26:24 [debug] 3724#0: *3 set http keepalive handler
2022/07/28 23:26:24 [debug] 3724#0: *3 http close request
2022/07/28 23:26:24 [debug] 3724#0: *3 http log handler
2022/07/28 23:26:24 [debug] 3724#0: *3 free: 000056372231DDE0, unused: 0
2022/07/28 23:26:24 [debug] 3724#0: *3 free: 00005637223135A0, unused: 2709
2022/07/28 23:26:24 [debug] 3724#0: *3 free: 000056372230E5C0
2022/07/28 23:26:24 [debug] 3724#0: *3 hc free: 0000000000000000
2022/07/28 23:26:24 [debug] 3724#0: *3 hc busy: 0000000000000000 0
2022/07/28 23:26:24 [debug] 3724#0: *3 tcp_nodelay
2022/07/28 23:26:24 [debug] 3724#0: *3 reusable connection: 1
2022/07/28 23:26:24 [debug] 3724#0: *3 event timer add: 3: 75000:31294444
2022/07/28 23:26:24 [debug] 3724#0: timer delta: 0
2022/07/28 23:26:24 [debug] 3724#0: worker cycle
2022/07/28 23:26:24 [debug] 3724#0: epoll timer: 75000
2022/07/28 23:26:24 [debug] 3724#0: epoll: fd:3 ev:2001 d:0000563722339E00
2022/07/28 23:26:24 [debug] 3724#0: *3 http keepalive handler
2022/07/28 23:26:24 [debug] 3724#0: *3 malloc: 000056372230E5C0:1024
2022/07/28 23:26:24 [debug] 3724#0: *3 recv: eof:1, avail:-1
2022/07/28 23:26:24 [debug] 3724#0: *3 recv: fd:3 0 of 1024
2022/07/28 23:26:24 [info] 3724#0: *3 client 127.0.0.1 closed keepalive connection
2022/07/28 23:26:24 [debug] 3724#0: *3 close http connection: 3
2022/07/28 23:26:24 [debug] 3724#0: *3 event timer del: 3: 31294444
2022/07/28 23:26:24 [debug] 3724#0: *3 reusable connection: 0
2022/07/28 23:26:24 [debug] 3724#0: *3 free: 000056372230E5C0
2022/07/28 23:26:24 [debug] 3724#0: *3 free: 0000563722317FF0, unused: 152
2022/07/28 23:26:24 [debug] 3724#0: timer delta: 4
2022/07/28 23:26:24 [debug] 3724#0: worker cycle
2022/07/28 23:26:24 [debug] 3724#0: epoll timer: -1
2022/07/28 23:26:28 [notice] 3728#0: signal process started
2022/07/28 23:26:28 [notice] 3723#0: signal 15 (SIGTERM) received from 3728, exiting
2022/07/28 23:26:28 [debug] 3723#0: wake up, sigio 0
2022/07/28 23:26:28 [debug] 3723#0: child: 0 3724 e:0 t:0 d:0 r:1 j:0
2022/07/28 23:26:28 [debug] 3723#0: termination cycle: 50
2022/07/28 23:26:28 [debug] 3723#0: sigsuspend
2022/07/28 23:26:28 [debug] 3724#0: epoll: fd:7 ev:0001 d:0000563722339D20
2022/07/28 23:26:28 [debug] 3724#0: channel handler
2022/07/28 23:26:28 [debug] 3724#0: channel: 32
2022/07/28 23:26:28 [debug] 3724#0: channel command: 4
2022/07/28 23:26:28 [debug] 3724#0: channel: -2
2022/07/28 23:26:28 [debug] 3724#0: timer delta: 4205
2022/07/28 23:26:28 [notice] 3724#0: exiting
2022/07/28 23:26:28 [debug] 3724#0: flush files
2022/07/28 23:26:28 [debug] 3724#0: run cleanup: 0000563722329758
2022/07/28 23:26:28 [debug] 3724#0: run cleanup: 0000563722326548
2022/07/28 23:26:28 [debug] 3724#0: cleanup resolver
2022/07/28 23:26:28 [debug] 3724#0: run cleanup: 00005637223114D0
2022/07/28 23:26:28 [debug] 3724#0: free: 000056372232D400
2022/07/28 23:26:28 [debug] 3724#0: free: 0000563722322A50
2022/07/28 23:26:28 [debug] 3724#0: free: 0000563722321990
2022/07/28 23:26:28 [debug] 3724#0: free: 00005637223208D0
2022/07/28 23:26:28 [debug] 3724#0: free: 000056372231F810
2022/07/28 23:26:28 [debug] 3724#0: free: 000056372230F590, unused: 0
2022/07/28 23:26:28 [debug] 3724#0: free: 00005637223185C0, unused: 0
2022/07/28 23:26:28 [debug] 3724#0: free: 0000563722323A60, unused: 0
2022/07/28 23:26:28 [debug] 3724#0: free: 0000563722327A70, unused: 8960
2022/07/28 23:26:28 [notice] 3724#0: exit
2022/07/28 23:26:28 [notice] 3723#0: signal 17 (SIGCHLD) received from 3724
2022/07/28 23:26:28 [notice] 3723#0: worker process 3724 exited with code 0
2022/07/28 23:26:28 [debug] 3723#0: shmtx forced unlock
2022/07/28 23:26:28 [debug] 3723#0: wake up, sigio 3
2022/07/28 23:26:28 [debug] 3723#0: reap children
2022/07/28 23:26:28 [debug] 3723#0: child: 0 3724 e:1 t:1 d:0 r:1 j:0
2022/07/28 23:26:28 [notice] 3723#0: exit
2022/07/28 23:26:28 [debug] 3723#0: close listening 0.0.0.0:8090 #6 
2022/07/28 23:26:28 [debug] 3723#0: run cleanup: 0000563722326548
2022/07/28 23:26:28 [debug] 3723#0: cleanup resolver
2022/07/28 23:26:28 [debug] 3723#0: run cleanup: 00005637223114D0
2022/07/28 23:26:28 [debug] 3723#0: free: 000056372232D400
2022/07/28 23:26:28 [debug] 3723#0: free: 0000563722322A50
2022/07/28 23:26:28 [debug] 3723#0: free: 0000563722321990
2022/07/28 23:26:28 [debug] 3723#0: free: 00005637223208D0
2022/07/28 23:26:28 [debug] 3723#0: free: 000056372231F810
2022/07/28 23:26:28 [debug] 3723#0: free: 000056372230F590, unused: 0
2022/07/28 23:26:28 [debug] 3723#0: free: 00005637223185C0, unused: 0
2022/07/28 23:26:28 [debug] 3723#0: free: 0000563722323A60, unused: 0
2022/07/28 23:26:28 [debug] 3723#0: free: 0000563722327A70, unused: 8987
stef commented 2 years ago

hey, sorry for this long silence. holidays, afk. i hope you're still interested in this. what would help immensely if you would recompile the main libopaque.so with -DTRACE it then spits out a lot of extra and very useful information that can help very quickly find out what is wrong.