search

OpenIDC / mod_oauth2

OAuth 2.x Resource Server module for the Apache HTTPd web server
Apache License 2.0
49 stars 14 forks source link

401 error when network hiccups #23

Closed GRRedWings closed 2 years ago

GRRedWings commented 3 years ago

I'm trying to track down why occasionally I get a 401 error .

Here is the configuration in Apache, it has a

<Location /someLocation> Require valid-user AuthType oauth2 OAuth2TokenVerify jwk "..." verify.iat=skip&expiry=5

This is the apache error I get 172.24.0.1 - FLCm7KqMmt-CnMOKmf1EpJYd5wbPUdJ8ILQPO_TT09Q [23/Aug/2021:16:20:40 +0000] "POST /someLocation/resources/vx.y/doIt HTTP/1.1" 200 186 double free or corruption (fasttop) 172.24.0.1 - - [23/Aug/2021:16:20:43 +0000] "POST /someLocation/resources/vx.y/doIt HTTP/1.1" 401 381 [Mon Aug 23 16:20:43.903993 2021] [core:notice] [pid 1:tid 139697330451584] AH00052: child pid 93 exit signal Aborted (6)

Am I reading this right that some sort of partial request is being processed and causing a memory error?

zandbelt commented 3 years ago

that looks like a memory corruption indeed, can you confirm you're using the latest version of module+library and are you able to produce a coredump+stacktrace?

GRRedWings commented 3 years ago

I admit that the version is a few months old. Probably Jan/Feb vintage. Do you know offhand how to produce those coredump/stacktarce? I can try to figure it out. I'm running this in a docker image.

zandbelt commented 3 years ago

ok, just send me the Dockerfile and I'll figure it out

GRRedWings commented 3 years ago

I'm going to try to update the versions of your libraries and Apache. but here is the dockerfile I'm running with.

FROM httpd:2.4

# Change this from a copy, to me having the deb files for both
RUN mkdir -p /tmp

COPY libhiredis0.13_0.13.3-2.2_amd64.deb /tmp/libhiredis0.13_0.13.3-2.2_amd64.deb
COPY libcjose0_0.6.1.5-1_bionic+1_amd64.deb /tmp/libcjose0_0.6.1.5-1_bionic+1_amd64.deb
COPY liboauth2_1.4.0.1-1.bionic+1_amd64.deb /tmp/liboauth2_1.4.0.1-1.bionic+1_amd64.deb
COPY liboauth2-apache_1.4.0.1-1.bionic+1_amd64.deb /tmp/liboauth2-apache_1.4.0.1-1.bionic+1_amd64.deb
COPY libapache2-mod-oauth2_3.2.0-1.bionic+1_amd64.deb /tmp/libapache2-mod-oauth2_3.2.0-1.bionic+1_amd64.deb
COPY libapache2-mod-auth-openidc_2.4.5-1.bionic+1_amd64.deb /tmp/libapache2-mod-auth-openidc_2.4.5-1.bionic+1_amd64.deb

RUN apt-get update && \
#    apt-get install -y ca-certificates libssl-dev check libjansson-dev libz-dev apache2 libmemcached-dev
    apt-get install -y ca-certificates apache2 libmemcached-dev

# Install the packages we just copied in
run dpkg -i /tmp/libhiredis0.13_0.13.3-2.2_amd64.deb
run dpkg -i /tmp/libcjose0_0.6.1.5-1_bionic+1_amd64.deb
run dpkg -i /tmp/liboauth2_1.4.0.1-1.bionic+1_amd64.deb
run dpkg -i /tmp/liboauth2-apache_1.4.0.1-1.bionic+1_amd64.deb
run dpkg -i /tmp/libapache2-mod-oauth2_3.2.0-1.bionic+1_amd64.deb
run dpkg -i /tmp/libapache2-mod-auth-openidc_2.4.5-1.bionic+1_amd64.deb

# Modify the httpd.conf to load modules we use, and tell it to use our custom.conf
RUN echo "LoadModule proxy_module modules/mod_proxy.so" >> /usr/local/apache2/conf/httpd.conf
RUN echo "LoadModule proxy_http_module modules/mod_proxy_http.so" >> /usr/local/apache2/conf/httpd.conf
RUN echo "LoadModule ssl_module modules/mod_ssl.so" >> /usr/local/apache2/conf/httpd.conf
RUN echo "LoadModule oauth2_module /usr/lib/apache2/modules/mod_oauth2.so" >> /usr/local/apache2/conf/httpd.conf
RUN echo "LoadModule auth_openidc_module /usr/lib/apache2/modules/mod_auth_openidc.so" >> /usr/local/apache2/conf/httpd.conf

RUN mkdir /usr/local/apache2/conf-available
RUN touch /usr/local/apache2/conf-available/custom.conf
RUN echo "Include conf-available/custom.conf" >> /usr/local/apache2/conf/httpd.conf
GRRedWings commented 3 years ago

172.27.0.1 - - [23/Aug/2021:18:16:15 +0000] "POST /someLocation/resources/x.y/doIt HTTP/1.1" 401 381 double free or corruption (fasttop) 172.27.0.1 - FLCm7KqMmt-CnMOKmf1EpJYd5wbPUdJ8ILQPO_TT09Q [23/Aug/2021:18:16:15 +0000] "POST /someLocation/resources/x.y/alsoDoIt/F443EE26 HTTP/1.1" 200 186 [Mon Aug 23 18:16:16.117599 2021] [core:notice] [pid 1:tid 140301462574208] AH00052: child pid 93 exit signal Aborted (6)

I think I upgraded to the lastest version of your libraries. And still got the error. I seem to get it in conjunctions with my Android device having a network blip.

FROM httpd:2.4

RUN mkdir -p /tmp

COPY libhiredis0.13_0.13.3-2.2_amd64.deb /tmp/libhiredis0.13_0.13.3-2.2_amd64.deb COPY libcjose0_0.6.1.5-1_bionic+1_amd64.deb /tmp/libcjose0_0.6.1.5-1_bionic+1_amd64.deb COPY liboauth2_1.4.3-1.bionic+1_amd64.deb /tmp/liboauth2_1.4.3-1.bionic+1_amd64.deb COPY liboauth2-apache_1.4.3-1.bionic+1_amd64.deb /tmp/liboauth2-apache_1.4.3-1.bionic+1_amd64.deb COPY libapache2-mod-oauth2_3.2.0-1.bionic+1_amd64.deb /tmp/libapache2-mod-oauth2_3.2.0-1.bionic+1_amd64.deb COPY libapache2-mod-auth-openidc_2.4.9.2-1.bionic+1_amd64.deb /tmp/libapache2-mod-auth-openidc_2.4.9.2-1.bionic+1_amd64.deb

RUN apt-get update && \ apt-get install -y ca-certificates apache2 libmemcached-dev

run dpkg -i /tmp/libhiredis0.13_0.13.3-2.2_amd64.deb run dpkg -i /tmp/libcjose0_0.6.1.5-1_bionic+1_amd64.deb run dpkg -i /tmp/liboauth2_1.4.3-1.bionic+1_amd64.deb run dpkg -i /tmp/liboauth2-apache_1.4.3-1.bionic+1_amd64.deb run dpkg -i /tmp/libapache2-mod-oauth2_3.2.0-1.bionic+1_amd64.deb run dpkg -i /tmp/libapache2-mod-auth-openidc_2.4.9.2-1.bionic+1_amd64.deb

RUN echo "LoadModule proxy_module modules/mod_proxy.so" >> /usr/local/apache2/conf/httpd.conf RUN echo "LoadModule proxy_http_module modules/mod_proxy_http.so" >> /usr/local/apache2/conf/httpd.conf RUN echo "LoadModule ssl_module modules/mod_ssl.so" >> /usr/local/apache2/conf/httpd.conf RUN echo "LoadModule oauth2_module /usr/lib/apache2/modules/mod_oauth2.so" >> /usr/local/apache2/conf/httpd.conf RUN echo "LoadModule auth_openidc_module /usr/lib/apache2/modules/mod_auth_openidc.so" >> /usr/local/apache2/conf/httpd.conf

RUN mkdir /usr/local/apache2/conf-available RUN touch /usr/local/apache2/conf-available/custom.conf RUN echo "Include conf-available/custom.conf" >> /usr/local/apache2/conf/httpd.conf

zandbelt commented 3 years ago

I'm not able to reproduce: can you set the log level to debug and send me the error_log?

GRRedWings commented 3 years ago

What is the best way to send you the error log? with a link? Can I email it to you anywhere?

zandbelt commented 3 years ago

you can send it to support@zmartzone.eu

GRRedWings commented 3 years ago

Just checking in. Did you receive my email and logs?

zandbelt commented 3 years ago

I did but unfortunately it did not help me to reproduce so I have nothing to work from :-(

GRRedWings commented 3 years ago

Any chance there are newer versions of these libraries and I'm just out of date?

COPY libhiredis0.13_0.13.3-2.2_amd64.deb /tmp/libhiredis0.13_0.13.3-2.2_amd64.deb COPY libcjose0_0.6.1.5-1_bionic+1_amd64.deb /tmp/libcjose0_0.6.1.5-1_bionic+1_amd64.deb COPY libapache2-mod-oauth2_3.2.0-1.bionic+1_amd64.deb /tmp/libapache2-mod-oauth2_3.2.0-1.bionic+1_amd64.deb

zandbelt commented 3 years ago

I tried to reproduce with your Dockerfile+versions, but no luck

GRRedWings commented 3 years ago

Also to be sure. I feel that the issue is with our Android application (using OkHttp), and if the network blips on the Android device, that's when I get the 401. It also seems like for some reason that there is some sort of timing. I'm going to write some other tests to see if I can repeat this easier.

GRRedWings commented 3 years ago

I've spent some more time trying to re-produce or find out what is going on. Based on your chance to look at the logs, do you have any clues on what is going on? Is it bad or partial data coming in? Is there something in the module that might be a problem? I'm kinda at a loss of where to dig.

zandbelt commented 3 years ago

I'm lost too; I would assume that partial data would lead to other, Apache-level errors

zandbelt commented 2 years ago

a double free error was solved in liboauth 1.4.4.1 https://github.com/zmartzone/liboauth2/releases/tag/v1.4.4.1; could this fix your issue as well? @GRRedWings please confirm

GRRedWings commented 2 years ago

I just updated everything and tested (1.4.4.2). This did not fix my problem. I still have not been able to track it down. But I know if I try to make calls from my laptop I don't get the issue. But if I make them from an Android device using appauth for Android I do still get the issues in certain scenarios.

GRRedWings commented 2 years ago

I'm trying to gather come more information. But here is what I have so far.

If I increase logging to trace8, it seems like the problem doesn't happen.

At trace6 I got these logs around the failure.

[Mon Jul 25 11:21:19.319811 2022] [oauth2:debug] [pid 93:tid 140228215936768] src/jose.c(934): [client 172.26.0.1:41202] _oauth2_jose_jwt_verify_jwk: leave: rc=0 [Mon Jul 25 11:21:19.319813 2022] [oauth2:debug] [pid 93:tid 140228215936768] src/jose.c(1333): [client 172.26.0.1:41202] oauth2_jose_jwt_verify: leave: 0 [Mon Jul 25 11:21:19.319814 2022] [oauth2:debug] [pid 93:tid 140228215936768] src/oauth2.c(848): [client 172.26.0.1:41202] oauth2_token_verify: leave: 0 [Mon Jul 25 11:21:19.319814 2022] [oauth2:debug] [pid 93:tid 140228215936768] src/server/apache.c(364): [client 172.26.0.1:41202] oauth2_apache_return_www_authenticate: enter [Mon Jul 25 11:21:19.319816 2022] [oauth2:debug] [pid 93:tid 140228215936768] src/server/apache.c(456): [client 172.26.0.1:41202] oauth2_apache_hdr_out_add: WWW-Authenticate: Bearer error="invalid_token", error_description="Token could not be verified." [Mon Jul 25 11:21:19.319818 2022] [oauth2:debug] [pid 93:tid 140228215936768] src/server/apache.c(388): [client 172.26.0.1:41202] oauth2_apache_return_www_authenticate: leave [Mon Jul 25 11:21:19.319818 2022] [oauth2:debug] [pid 93:tid 140228215936768] src/mod_oauth2.c(144): [client 172.26.0.1:41202] oauth2_request_handler: leave [Mon Jul 25 11:21:19.319819 2022] [core:trace3] [pid 93:tid 140228215936768] request.c(120): [client 172.26.0.1:41202] auth phase 'check user' gave status 401: /my/resources/v1.0/log/C6565BB1 [Mon Jul 25 11:21:19.319840 2022] [headers:debug] [pid 93:tid 140228215936768] mod_headers.c(890): AH01503: headers: ap_headers_error_filter() [Mon Jul 25 11:21:19.319851 2022] [http:trace3] [pid 93:tid 140228215936768] http_filters.c(1129): [client 172.26.0.1:41202] Response sent with status 401, headers: [Mon Jul 25 11:21:19.319852 2022] [http:trace5] [pid 93:tid 140228215936768] http_filters.c(1138): [client 172.26.0.1:41202] Date: Mon, 25 Jul 2022 11:21:19 GMT [Mon Jul 25 11:21:19.319852 2022] [http:trace5] [pid 93:tid 140228215936768] http_filters.c(1141): [client 172.26.0.1:41202] Server: Apache [Mon Jul 25 11:21:19.319853 2022] [http:trace4] [pid 93:tid 140228215936768] http_filters.c(959): [client 172.26.0.1:41202] Access-Control-Allow-Credentials: true [Mon Jul 25 11:21:19.319854 2022] [http:trace4] [pid 93:tid 140228215936768] http_filters.c(959): [client 172.26.0.1:41202] Access-Control-Allow-Origin: my-server:8080 [Mon Jul 25 11:21:19.319855 2022] [http:trace4] [pid 93:tid 140228215936768] http_filters.c(959): [client 172.26.0.1:41202] Access-Control-Allow-Methods: POST, GET, OPTIONS, DELETE, PUT [Mon Jul 25 11:21:19.319855 2022] [http:trace4] [pid 93:tid 140228215936768] http_filters.c(959): [client 172.26.0.1:41202] Access-Control-Max-Age: 1000 [Mon Jul 25 11:21:19.319856 2022] [http:trace4] [pid 93:tid 140228215936768] http_filters.c(959): [client 172.26.0.1:41202] Access-Control-Allow-Headers: x-requested-with, Content-Type, origin, authorization, accept, client-security-token [Mon Jul 25 11:21:19.319857 2022] [http:trace4] [pid 93:tid 140228215936768] http_filters.c(959): [client 172.26.0.1:41202] WWW-Authenticate: Bearer error=\"invalid_token\", error_description=\"Token could not be verified.\" [Mon Jul 25 11:21:19.319858 2022] [http:trace4] [pid 93:tid 140228215936768] http_filters.c(959): [client 172.26.0.1:41202] Content-Length: 381 [Mon Jul 25 11:21:19.319860 2022] [http:trace4] [pid 93:tid 140228215936768] http_filters.c(959): [client 172.26.0.1:41202] Keep-Alive: timeout=5, max=100 [Mon Jul 25 11:21:19.319860 2022] [http:trace4] [pid 93:tid 140228215936768] http_filters.c(959): [client 172.26.0.1:41202] Connection: Keep-Alive [Mon Jul 25 11:21:19.319881 2022] [http:trace4] [pid 93:tid 140228215936768] http_filters.c(959): [client 172.26.0.1:41202] Content-Type: text/html; charset=iso-8859-1 [Mon Jul 25 11:21:19.319884 2022] [ssl:trace4] [pid 93:tid 140228215936768] ssl_engine_io.c(1853): [client 172.26.0.1:41202] coalesce: have 0 bytes, adding 598 more (buckets=1) [Mon Jul 25 11:21:19.319885 2022] [ssl:trace4] [pid 93:tid 140228215936768] ssl_engine_io.c(1853): [client 172.26.0.1:41202] coalesce: have 598 bytes, adding 381 more (buckets=1) [Mon Jul 25 11:21:19.319886 2022] [ssl:trace4] [pid 93:tid 140228215936768] ssl_engine_io.c(1916): [client 172.26.0.1:41202] coalesce: passing on 979 bytes [Mon Jul 25 11:21:19.319888 2022] [ssl:trace6] [pid 93:tid 140228215936768] ssl_engine_io.c(891): [client 172.26.0.1:41202] ssl_filter_write: 979 bytes [Mon Jul 25 11:21:19.319912 2022] [ssl:trace6] [pid 93:tid 140228215936768] ssl_engine_io.c(218): [client 172.26.0.1:41202] bio_filter_out_write: 1001 bytes [Mon Jul 25 11:21:19.319921 2022] [ssl:trace4] [pid 93:tid 140228215936768] ssl_engine_io.c(2401): [client 172.26.0.1:41202] OpenSSL: write 1001/1001 bytes to BIO#7f895000bfb0 [mem: 7f892c004cc3] [Mon Jul 25 11:21:19.319928 2022] [ssl:trace4] [pid 93:tid 140228215936768] ssl_engine_io.c(2411): [client 172.26.0.1:41202] OpenSSL: I/O error, 5 bytes expected to read on BIO#7f894c00a6c0 [mem: 7f892c004cc3] 172.26.0.1 - - [25/Jul/2022:11:21:19 +0000] "POST /my/resources/v1.0/log/C6565BB1 HTTP/1.1" 401 381 [Mon Jul 25 11:21:19.319965 2022] [core:trace6] [pid 93:tid 140228215936768] core_filters.c(828): [client 172.26.0.1:41202] writev_nonblocking: 1001/1001 [Mon Jul 25 11:21:19.319993 2022] [oauth2:debug] [pid 93:tid 140228215936768] src/server/apache.c(332): [client 172.26.0.1:41202] oauth2_apache_request_context_free: dispose request context: 0x7f892c00bb70 double free or corruption (fasttop) [Mon Jul 25 11:21:19.499844 2022] [core:notice] [pid 1:tid 140229033639232] AH00052: child pid 93 exit signal Aborted (6) [Mon Jul 25 11:21:19.499880 2022] [core:trace4] [pid 1:tid 140229033639232] mpm_common.c(538): mpm child 93 (gen 0/slot 3) exited [Mon Jul 25 11:21:19.499882 2022] [mpm_event:debug] [pid 1:tid 140229033639232] event.c(715): Child 3 stopped: pid 93, gen 0, active 3/16, total 3/4/16, quiescing 0 [Mon Jul 25 11:21:19.500430 2022] [core:trace4] [pid 1:tid 140229033639232] mpm_common.c(538): mpm child 121 (gen 0/slot 3) started [Mon Jul 25 11:21:19.500449 2022] [mpm_event:debug] [pid 1:tid 140229033639232] event.c(740): Child 3 started: pid 121, gen 0, active 4/16, total 4/4/16

zandbelt commented 2 years ago

it seems that the crash happens only after the token fails to verify and an attempt is made to return a legitimate 401 error; the logs just before would show why the token fails to validate and may provide more insight into what is going on

GRRedWings commented 2 years ago

Thank you for looking at this. I have sent you an email with the full log.

GRRedWings commented 2 years ago

In looking at the logs prior, it almost looks like maybe it's an issue with the timeout. If I change my expiry from 5 to 60, in my short test window it has not happened.

(expires=1658748075, now=1658748070)

It almost seems like my expiry is not long enough. I've set it to 5, and maybe when I have a network blip it's not enough time?

zandbelt commented 2 years ago

this should be fixed now in release 1.4.5 of liboauth2: https://github.com/zmartzone/liboauth2/releases/tag/v1.4.5 the issue would only appear with mod_oauth2 when using:

OAuth2TokenVerify jwk <key>

and was caused by using non-thread-safe functions cjose_jwk_retain and cjose_jwk_release in a multi-threaded setting

GRRedWings commented 2 years ago

I've done a bit of testing and I have not had the issue come up again. I think it's safe to say that you found my issue! I appreciate you spending the time to dig into this.