View Issue Details

IDProjectCategoryView StatusLast Update
0005031Talerbank (demonstrator)public2017-06-06 14:18
ReporterChristian GrothoffAssigned ToMarcello Stanisci 
PrioritynormalSeverityminorReproducibilityalways
Status closedResolutionfixed 
Platformi7OSDebian GNU/LinuxOS Versionsqueeze
Product VersionSVN HEAD 
Target Version0.3Fixed in Version0.3 
Summary0005031: bank logs: "Session data corrupted"
DescriptionI just launched a bank, logged in. No actual wallet operations. The logs say:

*** Operational MODE: single process ***
2017-05-24 21:34:40,368 settings INFO DJANGO_SETTINGS_MODULE: talerbank.settings
2017-05-24 21:34:40,370 settings INFO secret key not configured in TALER_BANK_SECRET_KEY env variable, generating random secret
2017-05-24 21:34:40,371 settings INFO dbname: postgres:///talerbank
2017-05-24 21:34:40,371 settings INFO currency: 'KUDOS'
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x55f9401de470 pid: 13669 (default app)
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 13669)
spawned uWSGI worker 1 (pid: 13676, cores: 1)
spawned uWSGI http 1 (pid: 13677)
24/May/2017:21:34:59 +0000 HTTP/1.1 GET / HTTP/1.1 => 302
Session data corrupted
2017-05-24 21:34:59,588 base WARNING Session data corrupted
24/May/2017:21:34:59 +0000 HTTP/1.1 GET /profile HTTP/1.1 => 302
Session data corrupted
2017-05-24 21:34:59,599 base WARNING Session data corrupted
24/May/2017:21:34:59 +0000 HTTP/1.1 GET /login/?next=/profile HTTP/1.1 => 200
24/May/2017:21:34:59 +0000 HTTP/1.1 GET /static/pure.css HTTP/1.1 => 200
24/May/2017:21:34:59 +0000 HTTP/1.1 GET /static/web-common/demo.css HTTP/1.1 => 200
24/May/2017:21:34:59 +0000 HTTP/1.1 GET /static/web-common/taler-fallback.css HTTP/1.1 => 200
24/May/2017:21:34:59 +0000 HTTP/1.1 GET /static/web-common/taler-wallet-lib.js HTTP/1.1 => 200
24/May/2017:21:34:59 +0000 HTTP/1.1 GET /favicon.ico HTTP/1.1 => 200
24/May/2017:21:35:01 +0000 HTTP/1.1 GET /accounts/register/ HTTP/1.1 => 200
24/May/2017:21:35:01 +0000 HTTP/1.1 GET /favicon.ico HTTP/1.1 => 200
Session data corrupted
2017-05-24 21:35:04,188 base WARNING Session data corrupted
TagsNo tags attached.

Activities

Florian Dold

2017-05-27 15:10

manager   ~0012162

Eh, this is pretty normal. When the bank starts, it generates a secret to encrypt cookies (all done automatically by django). We could persist this secret somewhere, but that's IMHO not necessary.

All that this leads to is that the user needs to re-authenticate every time the bank restarts, which is very reasonable.

Christian Grothoff

2017-05-28 12:45

manager   ~0012163

Well, there are two bad things here still:
1) We log the warning twice, in fact many more times, but each time twice;
2) We log an incomprehensible warning. If it is truly harmless, it should not be this scary or suppressed.

Overall, I'm fine with not storing the secret to encrypt the cookies, but I don't understand why I get it for more than just the first connection after restart, that does suggests the issue is more serious. If it was just the restart, then a fresh cookie should have been set after the 1st connection and the subsequent requests should not generate the message, right?

Florian Dold

2017-05-28 13:02

manager   ~0012164

I would expect that Django logs the warning more than once, because we log it for every HTTP request the browser makes until we manage to log in again. Cookies are sent with every request.

It does not go away after the first request, because the response to this request doesn't set any cookie.

Of course Django could have logic to clear a corrupted session cookie, but they decided not to do that. Django could also log a less scary warning, but they decided not to. There's nothing reasonable we can do here, other than to persist the secret.

Florian Dold

2017-05-28 13:05

manager   ~0012165

Note that in the logs above, the warning gets printed exactly for every request that is handled by django views (and not by static files). So Django just automatically tries to decrypt the cookie here ...

Christian Grothoff

2017-05-28 14:15

manager   ~0012166

Well, if we can't easily do something about the logs, then I guess this is done.

Issue History

Date Modified Username Field Change
2017-05-24 23:36 Christian Grothoff New Issue
2017-05-24 23:36 Christian Grothoff Status new => assigned
2017-05-24 23:36 Christian Grothoff Assigned To => Marcello Stanisci
2017-05-27 15:10 Florian Dold Status assigned => resolved
2017-05-27 15:10 Florian Dold Resolution open => fixed
2017-05-27 15:10 Florian Dold Note Added: 0012162
2017-05-28 12:45 Christian Grothoff Note Added: 0012163
2017-05-28 12:45 Christian Grothoff Status resolved => feedback
2017-05-28 12:45 Christian Grothoff Resolution fixed => reopened
2017-05-28 13:02 Florian Dold Note Added: 0012164
2017-05-28 13:05 Florian Dold Note Added: 0012165
2017-05-28 14:15 Christian Grothoff Status feedback => assigned
2017-05-28 14:15 Christian Grothoff Resolution reopened => no change required
2017-05-28 14:15 Christian Grothoff Fixed in Version => 0.3
2017-05-28 14:15 Christian Grothoff Note Added: 0012166
2017-05-28 14:16 Christian Grothoff Status assigned => resolved
2017-05-28 14:16 Christian Grothoff Resolution no change required => fixed
2017-06-06 14:18 Christian Grothoff Status resolved => closed