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.

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

Strange behavior of Admin UI login #738

Closed
muhlemmer opened this issue Dec 10, 2018 · 21 comments · Fixed by #743
Closed

Strange behavior of Admin UI login #738

muhlemmer opened this issue Dec 10, 2018 · 21 comments · Fixed by #743
Labels
priority/p0 Critical bug without workaround / Must have type/bug Bug. Not working as intended

Comments

@muhlemmer
Copy link
Member

As discussed on Matrix. It seems that the login "failures" as noted in #670 are back.

In short

When doing a login on the admin UI, it happens from time to time that the login screen is presented once again. Looking in the logs, the POST is returned with a status 200 (success), instead of a 302 (redirect). This behavior is not consistent. Also, it seems that this behavior affects other POST requests, like creating a domain.

It seems that the behavior exposes more in my production environment, 2 out 3 POST request don't work. This environment is on Docker Swarm, with a replicated front and a single Admin. main.db resides on a local file system. This might be due to the Docker env, network or the fact that the DB originated from a 1.5 installation.

Reproduction

I was able to reproduce this on a test server with docker-compose setup. However, the behavior expresses less frequent. (Perhaps 1 out of 5). On this environment it seems that it did not expose using a database created with the latest master, only with an updated database.

Checkout a version from before the merge of #670. Build images, run mailu and setup the first user.

sudo rm -rfv /mailu
git checkout fee52e87eddbf445b15359eea95cde576bc13666
export MAILU_VERSION="master"
docker-compose -f tests/build.yml build
cd <to compose file>
docker-compose up -d
docker-compose exec admin python3 manage.py admin admin usrpro.io Simple123

At this stage I verified that login behaved "normal". I logged out and proceeded to update.

git checkout upstream/master
docker-compose -f tests/build.yml build
docker-compose up -d

Now, during log-in the behavior exposed as described above. Here are the admin container logs:

admin_1      | 188.27.138.94 - - [10/Dec/2018:12:49:53 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 200 4395 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:05 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 302 227 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:05 +0000] "GET /ui/ HTTP/1.0" 302 253 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:06 +0000] "GET /ui/user/settings HTTP/1.0" 200 7535 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 127.0.0.1 - - [10/Dec/2018:12:50:07 +0000] "GET /ui/login?next=ui.index HTTP/1.1" 200 4308 "-" "curl/7.61.1"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:09 +0000] "GET /ui/logout HTTP/1.0" 302 227 "https://mail.usrpro.io/admin/ui/user/settings" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:09 +0000] "GET /ui/ HTTP/1.0" 302 265 "https://mail.usrpro.io/admin/ui/user/settings" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:09 +0000] "GET /ui/login?next=ui.index HTTP/1.0" 200 4380 "https://mail.usrpro.io/admin/ui/user/settings" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:14 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 200 4395 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:18 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 302 227 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:18 +0000] "GET /ui/ HTTP/1.0" 302 253 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:19 +0000] "GET /ui/user/settings HTTP/1.0" 200 7535 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:20 +0000] "GET /ui/logout HTTP/1.0" 302 227 "https://mail.usrpro.io/admin/ui/user/settings" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:20 +0000] "GET /ui/ HTTP/1.0" 302 265 "https://mail.usrpro.io/admin/ui/user/settings" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:20 +0000] "GET /ui/login?next=ui.index HTTP/1.0" 200 4380 "https://mail.usrpro.io/admin/ui/user/settings" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:23 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 302 227 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:23 +0000] "GET /ui/ HTTP/1.0" 302 253 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:23 +0000] "GET /ui/user/settings HTTP/1.0" 200 7535 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:25 +0000] "GET /ui/logout HTTP/1.0" 302 227 "https://mail.usrpro.io/admin/ui/user/settings" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:25 +0000] "GET /ui/ HTTP/1.0" 302 265 "https://mail.usrpro.io/admin/ui/user/settings" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:25 +0000] "GET /ui/login?next=ui.index HTTP/1.0" 200 4380 "https://mail.usrpro.io/admin/ui/user/settings" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:28 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 302 227 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:28 +0000] "GET /ui/ HTTP/1.0" 302 253 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:12:50:28 +0000] "GET /ui/user/settings HTTP/1.0" 200 7535 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"

You can see that there are two POST requests that returned a 200. This where the ones where login did not work as supposed. All the other output are the succeeded attempts.

@muhlemmer
Copy link
Member Author

Database file from the test server: https://we.tl/t-sB4tAC4Dwd

@muhlemmer
Copy link
Member Author

@muhlemmer
Copy link
Member Author

I did a fresh install of 1.5 and upgraded to latest master. This seems to trigger the behavior at the same frequency as I'm seeing in production!

Logs don't tell much:

admin_1      | 188.27.138.94 - - [10/Dec/2018:14:48:30 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 200 4395 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:14:48:34 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 200 4395 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:14:48:37 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 200 4395 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [10/Dec/2018:14:48:39 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 200 4395 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"

Basically I did:

sudo rm -rfv /mailu
cd <to compose file for 1.5>
docker-compose up -d
docker-compose exec python manage.py admin admin usrpro.io Simple123
<Verify login>
docker-compose down
cd <to compose file for master>
docker-compose up -d
docker-compose logs -f admin

After waiting for things to settle, I tried login in. Couldn't login, even after 20x

@hoellen
Copy link
Member

hoellen commented Dec 10, 2018

I could also reproduce this behavior, when I want to create an alias. I noticed it when testing #737
It seems very random and the logs only contains the following:

admin_1      | 172.21.0.1 - - [10/Dec/2018:15:25:22 +0000] "POST /ui/alias/create/example.com HTTP/1.0" 200 11960 "http://172.21.0.10/settings/ui/alias/create/example.com" "Mozilla/5.0 (X11; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"

Normally there is (as you mentioned) a 302 redirect after successfully creating an alias:

admin_1      | 172.21.0.1 - - [10/Dec/2018:15:22:35 +0000] "POST /ui/alias/create/example.com HTTP/1.0" 302 275 "http://172.21.0.10/settings/ui/alias/create/example.com" "Mozilla/5.0 (X11; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 172.21.0.1 - - [10/Dec/2018:15:22:35 +0000] "GET /ui/alias/list/example.com HTTP/1.0" 200 27473 "http://172.21.0.10/settings/ui/alias/create/example.com" "Mozilla/5.0 (X11; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"

I could pass it with smashing the "Save" button very often.

Also the behavior with the login page happens sometimes on my dev environment.

@muhlemmer
Copy link
Member Author

Finally got screen recording to work 😆 . But I'm glad someone else can reproduce it. Almost started to worry it was the phase of the moon or something.
https://youtu.be/KPCHoh6RtFU

@kaiyou
Copy link
Member

kaiyou commented Dec 10, 2018

I cannot reproduce the issue so I am mostly fishing. Not everything sounds consistent with it but it could be an issue with csrf checks. Could you try setting WTF_CSRF_ENABLED=False in the app configuration.py (or __init__.py if you are running the latest commits)?

Also, you mention the redirection failing. But in the case of an alias creation for instance, does the alias get created or does the whole create-then-redirect fail? The former would eliminate my first hypothesis while the latter woule make wtform checks, especially csrf, very probable culprits.

@kaiyou
Copy link
Member

kaiyou commented Dec 10, 2018

Could you check from the browser that all post requests, including the failing ones, contain a valid session cookie and the hidden csrf token as part of the submitted form?

@kaiyou
Copy link
Member

kaiyou commented Dec 10, 2018

Also, I am assuming there is no significant delay between displaying the page that contains the form and posting the form itself (meaning << 1 hour). Is that assumption correct?

@muhlemmer
Copy link
Member Author

So, one advancement. At one point login succeeded and I was not able to reproduce. After getting rid of the session cooky in my browser, this behavior came back. No new cookies are received at any point, even after a number of tried logins.
image

Recap:

  1. I deployed mailu:1.5, with SECRET_KEY still set to "ChangeMeChangeMe"
  2. I did docker-compose down
  3. I deployed mailu:master, with SECRET_KEY set to a random string (from setup)
  4. Delete all cookies
  5. Can't login

@muhlemmer
Copy link
Member Author

Small note, after changing SECRET_KEY to "ChangeMeChangeMe" in master's mailu.env, docker-compose down & up, I could login again. However, my colleague somehow still can't 🙄

@muhlemmer
Copy link
Member Author

muhlemmer commented Dec 11, 2018

Deleting the cookie again on my side continued the behavior. I'll continue with your suggestions now,

@muhlemmer
Copy link
Member Author

csrf token is set in the form.

image

@muhlemmer
Copy link
Member Author

csrf is actually set twice to the same value:
image

Setting 'WTF_CSRF_ENABLED': 'False', as entry of DEFAULT_CONFIG did not change the behavior. And crsf tokens are still present in the form.

@muhlemmer
Copy link
Member Author

Also, you mention the redirection failing. But in the case of an alias creation for instance, does the alias get created or does the whole create-then-redirect fail? The former would eliminate my first hypothesis while the latter woule make wtform checks, especially csrf, very probable culprits.

As a matter of fact, we first cam across this problem in our psql branch. Because I though we did something wrong, I enable full verbosity on the database logs, allowing us to see what's happening. I'll cite my comment from the PR:

It might be very interesting to know, that looking at the postresql logs, no log-in queries are executed in cases where it didn't work. The only query that does get executed, is the one that lists the sign-up domains.

@ofthesun9
Copy link
Contributor

On my setup, the issue disappears if I set WEBROOT_REDIRECT=/admin

@hoellen
Copy link
Member

hoellen commented Dec 11, 2018

On my setup, the issue disappears if I set WEBROOT_REDIRECT=/admin

@ofthesun9 You are sure its because of the env variable? Because for me the issue disappear for a while, when I just doing docker-compose down and docker-compose up -d.

But in the case of an alias creation for instance, does the alias get created or does the whole create-then-redirect fail?

The alias doesn't get created. Only after clicking the Save button several times, the page is redirected and the alias created.

@ofthesun9
Copy link
Contributor

@hoellen
I just set the WEBROOT_REDIRECT=/admin

  • login was ok right first time.
  • creation of an alias was ok.

@ofthesun9
Copy link
Contributor

ofthesun9 commented Dec 11, 2018

Now, the other way around :-)
I just set WEBROOT_REDIRECT=/webmail
docker-compose up -d

  • login was ok at the 4th attempt
  • creation of an alias was ok at the 8th attempt

@muhlemmer
Copy link
Member Author

@ofthesun9: Changing WEBROOT_REDIRECT did not make any difference on my test server ;)

@kaiyou:
I've been able to reproduce it more simply now:

  1. Install a new Mailu deployment from master, create the first user
  2. Browse to the admin login page. Observe a session cookie is obtained
  3. Login, it works.
  4. Logout and manually delete the session cookie
  5. Refresh the page, no new session cookie is send
  6. Try to login, it won't work.

I don't believe we are managing the cookies directly in our app? I start to suspect flask-login to have a bug. I believe this was updated also in the admin refactor.

@muhlemmer muhlemmer added priority/p0 Critical bug without workaround / Must have type/bug Bug. Not working as intended labels Dec 11, 2018
@muhlemmer
Copy link
Member Author

It seem to be CSRF tokens issues. We've modified the `/login' view:

@ui.route('/login', methods=['GET', 'POST'])
def login():
    print(">>>>> Login route called",file=sys.stderr,flush=True)
    form = forms.LoginForm()
    print(request.form,file=sys.stderr,flush=True)
    if form.validate_on_submit():
        print(">>>>> Submit validated",file=sys.stderr,flush=True)
        user = models.User.login(form.email.data, form.pw.data)
        if user:
            print(">>>>> Calling flask login",file=sys.stderr,flush=True)
            print(user,file=sys.stderr,flush=True)
            flask_login.login_user(user)
            endpoint = flask.request.args.get('next', '.index')
            r = flask.redirect(flask.url_for(endpoint)
                or flask.url_for('.index'))
            print(">>>>> Return will be:",file=sys.stderr,flush=True)
            print(r,file=sys.stderr,flush=True)
            return r
        else:
            flask.flash('Wrong e-mail or password', 'error')
    for f, eM in form.errors.items():
        for e in eM:
            print(e,file=sys.stderr,flush=True)
    return flask.render_template('login.html', form=form)

This is giving us the following logs:

admin_1      | >>>>> Login route called
admin_1      | ImmutableMultiDict([('csrf_token', 'IjllYmQxM2E4YjM4OTk3NzQ5OGIzMWI0NzIxNzZhOWQ0MDI4NTA1MWIi.XBDWOw._cAQl6sf9TmkJRLVVoFmotalMJU'), ('csrf_token', 'IjllYmQxM2E4YjM4OTk3NzQ5OGIzMWI0NzIxNzZhOWQ0MDI4NTA1MWIi.XBDWOw._cAQl6sf9TmkJRLVVoFmotalMJU'), ('email', 'admin@usrpro.io'), ('pw', 'Simple123'), ('submit', 'Sign in')])
admin_1      | The CSRF session token is missing.
admin_1      | 188.27.138.94 - - [12/Dec/2018:09:34:57 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 200 4395 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"

Sometimes a cookie gets passed back to the browser. (Usually the first time after restarting the container). The request that return the cookie looks like:

 >>>>> Login route called
admin_1      | ImmutableMultiDict([('csrf_token', 'IjdjMjQwNGQ0MzcwNGM4MDYzNWEzYmRkOWM3NDQ0Y2VjMjVmYjdhY2Qi.XBDXqg.-jUYkwM2pOliQQjXqdJEGFv7d_0'), ('csrf_token', 'IjdjMjQwNGQ0MzcwNGM4MDYzNWEzYmRkOWM3NDQ0Y2VjMjVmYjdhY2Qi.XBDXqg.-jUYkwM2pOliQQjXqdJEGFv7d_0'), ('email', 'admin@usrpro.io'), ('pw', 'Simple123'), ('submit', 'Sign in')])
admin_1      | The CSRF tokens do not match.
admin_1      | 188.27.138.94 - - [12/Dec/2018:09:47:49 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 200 4395 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"

So now the mis-match gave us a session cookie. Subsequently, we can now login:

>>>>> Login route called
admin_1      | ImmutableMultiDict([('csrf_token', 'ImZlNTJhNDhiOGFmY2UxNzA3ZDU0MTVmMDY2ODQ4NDQ2ZmFiNTE0NzYi.XBDZRA.AV8TIGthmaVZthN_UofCCYFKvtY'), ('csrf_token', 'ImZlNTJhNDhiOGFmY2UxNzA3ZDU0MTVmMDY2ODQ4NDQ2ZmFiNTE0NzYi.XBDZRA.AV8TIGthmaVZthN_UofCCYFKvtY'), ('email', 'admin@usrpro.io'), ('pw', 'Simple123'), ('submit', 'Sign in')])
admin_1      | >>>>> Submit validated
admin_1      | >>>>> Calling flask login
admin_1      | admin@usrpro.io
admin_1      | >>>>> Return will be:
admin_1      | <Response 227 bytes [302 FOUND]>
admin_1      | 188.27.138.94 - - [12/Dec/2018:09:51:23 +0000] "POST /ui/login?next=ui.index HTTP/1.0" 302 227 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [12/Dec/2018:09:51:23 +0000] "GET /ui/ HTTP/1.0" 302 253 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [12/Dec/2018:09:51:24 +0000] "GET /ui/user/settings HTTP/1.0" 200 7535 "https://mail.usrpro.io/admin/ui/login?next=ui.index" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"

So now I logged out and deleted the cookie again. Browsing to the admin page (GET):

admin_1      | 188.27.138.94 - - [12/Dec/2018:09:55:02 +0000] "GET /ui/ HTTP/1.0" 302 265 "-" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | >>>>> Login route called
admin_1      | ImmutableMultiDict([])
admin_1      | 188.27.138.94 - - [12/Dec/2018:09:55:02 +0000] "GET /ui/login?next=ui.index HTTP/1.0" 200 4380 "-" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"
admin_1      | 188.27.138.94 - - [12/Dec/2018:09:55:03 +0000] "GET /static/bootstrap/css/bootstrap.min.css.map HTTP/1.0" 404 233 "-" "Mozilla/5.0 (X11; Fedora; Linux x86_64; rv:63.0) Gecko/20100101 Firefox/63.0"

No form errors, but also no cookie.

@muhlemmer
Copy link
Member Author

muhlemmer commented Dec 12, 2018

@kaiyou:
So we're giving up for the day. We are going on a small business trip tomorrow, so that's a bit inconvenient. If you don't find anything useful tonight, we might need to disable CSRF on master for the time being?

We have quite some injected code in https://github.com/usrpro/Mailu/tree/trouble. Maybe you want to reuse it. It includes the following:

  1. Some print statements to see code flow
  2. Middleware that dumps the request and response headers
  3. An direct call to flask_wtf to regenerate the token
  4. flask.session.permanent = True
  5. Print the contents of session.

We can see now, with setting of (4) a cookie is always send. Perfect. Put the cookie does not contain the CSRF token.... Somehow flask_wtf is not appending it to session. Not even when calling directly.

There are quite some changes to the flask session and cookie interface, but I could find anything apparent there either, but maybe it broke something in flask_wtf, which has not been updated after the release of flask 1.0?
http://flask.pocoo.org/docs/1.0/changelog/#version-1-0

kaiyou added a commit to kaiyou/Mailu that referenced this issue Dec 13, 2018
The init script was pushing an application context, which maked
flask.g global and persisted across requests. This was evaluated
to have a minimal security impact.

This explains/fixes Mailu#738: flask_wtf caches the csrf token in the
application context to have a single token per request, and only
sets the session attribute after the first generation.
muhlemmer added a commit that referenced this issue Dec 14, 2018
Fixes #738 regarding application context
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
priority/p0 Critical bug without workaround / Must have type/bug Bug. Not working as intended
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants