Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

401 error when network hiccups #23

Closed
GRRedWings opened this issue Aug 23, 2021 · 23 comments
Closed

401 error when network hiccups #23

GRRedWings opened this issue Aug 23, 2021 · 23 comments

Comments

@GRRedWings
Copy link

GRRedWings commented Aug 23, 2021 •
edited
Loading

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
Copy link
Member

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
Copy link
Author

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
Copy link
Member

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

@GRRedWings
Copy link
Author

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
Copy link
Author

GRRedWings commented Aug 23, 2021 •
edited
Loading

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
Copy link
Member

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

@GRRedWings
Copy link
Author

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

@zandbelt
Copy link
Member

you can send it to support@zmartzone.eu

@GRRedWings
Copy link
Author

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

@zandbelt
Copy link
Member

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

@GRRedWings
Copy link
Author

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
Copy link
Member

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

@GRRedWings
Copy link
Author

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
Copy link
Author

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
Copy link
Member

zandbelt commented Sep 2, 2021

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

@zandbelt
Copy link
Member

zandbelt commented Mar 3, 2022 •
edited
Loading

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
Copy link
Author

GRRedWings commented Jul 25, 2022 •
edited
Loading

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
Copy link
Author

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
Copy link
Member

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
Copy link
Author

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

@GRRedWings
Copy link
Author

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 added a commit that referenced this issue Jul 27, 2022
@zandbelt
release 3.2.3: depend on liboauth2 1.4.5
cc73e27 
with multi-treading fix for "OAuth2Verify jwk <key>"
see #23

Signed-off-by: Hans Zandbelt <hans.zandbelt@zmartzone.eu>
@zandbelt
Copy link
Member

zandbelt commented Jul 27, 2022 •
edited
Loading

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
Copy link
Author

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@zandbelt @GRRedWings