search

LukeMathWalker / zero-to-production

Code for "Zero To Production In Rust", a book on API development using Rust.
https://www.zero2prod.com
Apache License 2.0
5.43k stars 470 forks source link

Redirect to GET /admin/dashboard fails #240

Open psprojectC opened 6 months ago

psprojectC commented 6 months ago

I've been following the book up to the implementation of logging into /dashboard (page 371). After introducing the seeded user I cannot log into /dashboard. I have a reason to believe that the credentials are correct: image We can observe that there is indeed a redirect to dashboard which doesn't happen if I mess up the credentials. My assumption is actix_session fails in some way, if we look at the logs I've captured the userId key (I use camelCase in my version) is indeed stored in the session, but when it's time to retrieve it back the session is for some reason empty:

2023-12-26T20:00:22.680563Z ERROR zero2prod::sessionState: State after inserting: {
    "userId": "\"ddf8994f-d522-4659-8d02-c1d479057be6\"",
}
    at src/sessionState.rs:19
    in zero2prod::routes::login::post::login with userId: ddf8994f-d522-4659-8d02-c1d479057be6
    in tracing_actix_web::root_span_builder::HTTP request with http.method: POST, http.route: /login, http.flavor: 1.1, http.scheme: http, http.host: <hidden ip>:8000, http.client_ip: <hidden ip>, http.user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:121.0) Gecko/20100101 Firefox/121.0, http.target: /login, otel.name: HTTP POST /login, otel.kind: "server", request_id: 496549a4-556e-4e9e-892f-2203ead118ed

  2023-12-26T20:00:22.680673Z  INFO zero2prod::routes::login::post: close, time.busy: 99.0ms, time.idle: 481ms
    at src/routes/login/post.rs:22
    in zero2prod::routes::login::post::login with userId: ddf8994f-d522-4659-8d02-c1d479057be6
    in tracing_actix_web::root_span_builder::HTTP request with http.method: POST, http.route: /login, http.flavor: 1.1, http.scheme: http, http.host: <hidden ip>:8000, http.client_ip: <hidden ip>, http.user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:121.0) Gecko/20100101 Firefox/121.0, http.target: /login, otel.name: HTTP POST /login, otel.kind: "server", request_id: 496549a4-556e-4e9e-892f-2203ead118ed

  2023-12-26T20:00:22.690216Z  INFO tracing_actix_web::root_span_builder: close, time.busy: 100ms, time.idle: 491ms
    at /home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-actix-web-0.5.1/src/root_span_builder.rs:40
    in tracing_actix_web::root_span_builder::HTTP request with http.method: POST, http.route: /login, http.flavor: 1.1, http.scheme: http, http.host: <hidden ip>:8000, http.client_ip: <hidden ip>, http.user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:121.0) Gecko/20100101 Firefox/121.0, http.target: /login, otel.name: HTTP POST /login, otel.kind: "server", request_id: 496549a4-556e-4e9e-892f-2203ead118ed, http.status_code: 303, otel.status_code: "OK"

  2023-12-26T20:00:22.708296Z ERROR zero2prod::sessionState: State before getting: {}
    at src/sessionState.rs:25
    in tracing_actix_web::root_span_builder::HTTP request with http.method: GET, http.route: /admin/dashboard, http.flavor: 1.1, http.scheme: http, http.host: <hidden ip>:8000, http.client_ip: <hidden ip>, http.user_agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:121.0) Gecko/20100101 Firefox/121.0, http.target: /admin/dashboard, otel.name: HTTP GET /admin/dashboard, otel.kind: "server", request_id: 7dbcb599-e4ac-41dc-bcdb-158f2e68c0d2

(I log them as ERROR so that it appears as red in the logs and is easier to spot)

I repeated this experiment with the main branch version of the app. After cloning it, running both init scripts (and changing the host in local.yaml from 127.0.0.1 to 0.0.0.0) I get the same behavior. I'll attach the logs (with minor edits):

{
  "msg": "starting 8 workers",
  "time": "2023-12-26T20:07:28.836994354Z",
  "target": "actix_server::builder",
  "line": 240,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/builder.rs"
}
{
  "msg": "Tokio runtime found; starting in existing Tokio runtime",
  "time": "2023-12-26T20:07:28.837272554Z",
  "target": "actix_server::server",
  "line": 197,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/server.rs"
}
{
  "msg": "[TRY_EXECUTE_TASK - START]",
  "time": "2023-12-26T20:07:28.838262754Z",
  "target": "zero2prod::issue_delivery_worker",
  "line": 33,
  "file": "src/issue_delivery_worker.rs"
}
{
  "msg": "[DEQUEUE_TASK - START]",
  "time": "2023-12-26T20:07:28.838409454Z",
  "target": "zero2prod::issue_delivery_worker",
  "line": 88,
  "file": "src/issue_delivery_worker.rs"
}
{
  "msg": "[DEQUEUE_TASK - END]",
  "time": "2023-12-26T20:07:28.943876051Z",
  "target": "zero2prod::issue_delivery_worker",
  "line": 88,
  "file": "src/issue_delivery_worker.rs",
  "elapsed_milliseconds": 105
}
{
  "msg": "[TRY_EXECUTE_TASK - END]",
  "time": "2023-12-26T20:07:28.943966251Z",
  "target": "zero2prod::issue_delivery_worker",
  "line": 33,
  "file": "src/issue_delivery_worker.rs",
  "elapsed_milliseconds": 105
}
{
  "msg": "[HTTP REQUEST - START]",
  "time": "2023-12-26T20:07:31.128064821Z",
  "target": "tracing_actix_web::root_span_builder",
  "line": 41,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-actix-web-0.7.6/src/root_span_builder.rs",
  "http.client_ip": "<hidden ip>",
  "http.route": "/login",
  "otel.name": "HTTP POST /login",
  "http.scheme": "http",
  "otel.kind": "server",
  "request_id": "96888033-a15a-49e1-a594-276a55c467a5",
  "http.method": "POST",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.target": "/login"
}
{
  "msg": "[LOGIN - START]",
  "time": "2023-12-26T20:07:31.128609719Z",
  "target": "zero2prod::routes::login::post",
  "line": 19,
  "file": "src/routes/login/post.rs",
  "http.client_ip": "<hidden ip>",
  "http.route": "/login",
  "otel.name": "HTTP POST /login",
  "http.scheme": "http",
  "otel.kind": "server",
  "request_id": "96888033-a15a-49e1-a594-276a55c467a5",
  "http.method": "POST",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.target": "/login"
}
{
  "msg": "[VALIDATE CREDENTIALS - START]",
  "time": "2023-12-26T20:07:31.128855119Z",
  "target": "zero2prod::authentication::password",
  "line": 41,
  "file": "src/authentication/password.rs",
  "http.client_ip": "<hidden ip>",
  "http.route": "/login",
  "otel.name": "HTTP POST /login",
  "http.scheme": "http",
  "otel.kind": "server",
  "request_id": "96888033-a15a-49e1-a594-276a55c467a5",
  "http.method": "POST",
  "username": "admin",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.target": "/login"
}
{
  "msg": "[GET STORED CREDENTIALS - START]",
  "time": "2023-12-26T20:07:31.128987118Z",
  "target": "zero2prod::authentication::password",
  "line": 21,
  "file": "src/authentication/password.rs",
  "http.client_ip": "<hidden ip>",
  "http.route": "/login",
  "otel.name": "HTTP POST /login",
  "http.scheme": "http",
  "otel.kind": "server",
  "request_id": "96888033-a15a-49e1-a594-276a55c467a5",
  "http.method": "POST",
  "username": "admin",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.target": "/login"
}
{
  "msg": "[GET STORED CREDENTIALS - END]",
  "time": "2023-12-26T20:07:31.267104282Z",
  "target": "zero2prod::authentication::password",
  "line": 21,
  "file": "src/authentication/password.rs",
  "http.client_ip": "<hidden ip>",
  "http.route": "/login",
  "otel.name": "HTTP POST /login",
  "http.scheme": "http",
  "otel.kind": "server",
  "request_id": "96888033-a15a-49e1-a594-276a55c467a5",
  "http.method": "POST",
  "elapsed_milliseconds": 137,
  "username": "admin",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.target": "/login"
}
{
  "msg": "[VALIDATE CREDENTIALS - START]",
  "time": "2023-12-26T20:07:31.267516881Z",
  "target": "zero2prod::authentication::password",
  "line": 72,
  "file": "src/authentication/password.rs",
  "http.client_ip": "<hidden ip>",
  "http.route": "/login",
  "otel.name": "HTTP POST /login",
  "http.scheme": "http",
  "otel.kind": "server",
  "request_id": "96888033-a15a-49e1-a594-276a55c467a5",
  "http.method": "POST",
  "username": "admin",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.target": "/login"
}
{
  "msg": "[VALIDATE CREDENTIALS - END]",
  "time": "2023-12-26T20:07:31.985535235Z",
  "target": "zero2prod::authentication::password",
  "line": 72,
  "file": "src/authentication/password.rs",
  "http.client_ip": "<hidden ip>",
  "http.route": "/login",
  "otel.name": "HTTP POST /login",
  "http.scheme": "http",
  "otel.kind": "server",
  "request_id": "96888033-a15a-49e1-a594-276a55c467a5",
  "http.method": "POST",
  "elapsed_milliseconds": 717,
  "username": "admin",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.target": "/login"
}
{
  "msg": "[VALIDATE CREDENTIALS - END]",
  "time": "2023-12-26T20:07:31.985977234Z",
  "target": "zero2prod::authentication::password",
  "line": 41,
  "file": "src/authentication/password.rs",
  "http.client_ip": "<hidden ip>",
  "http.route": "/login",
  "otel.name": "HTTP POST /login",
  "http.scheme": "http",
  "otel.kind": "server",
  "request_id": "96888033-a15a-49e1-a594-276a55c467a5",
  "http.method": "POST",
  "elapsed_milliseconds": 857,
  "username": "admin",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.target": "/login"
}
{
  "msg": "[LOGIN - END]",
  "time": "2023-12-26T20:07:31.986226634Z",
  "target": "zero2prod::routes::login::post",
  "line": 19,
  "file": "src/routes/login/post.rs",
  "http.client_ip": "<hidden ip>",
  "http.route": "/login",
  "otel.name": "HTTP POST /login",
  "http.scheme": "http",
  "otel.kind": "server",
  "request_id": "96888033-a15a-49e1-a594-276a55c467a5",
  "user_id": "ddf8994f-d522-4659-8d02-c1d479057be6",
  "http.method": "POST",
  "elapsed_milliseconds": 857,
  "username": "admin",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.target": "/login"
}
{
  "msg": "[HTTP REQUEST - END]",
  "time": "2023-12-26T20:07:31.98763833Z",
  "target": "tracing_actix_web::root_span_builder",
  "line": 41,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-actix-web-0.7.6/src/root_span_builder.rs",
  "http.client_ip": "<hidden ip>",
  "http.route": "/login",
  "otel.name": "HTTP POST /login",
  "http.scheme": "http",
  "otel.kind": "server",
  "request_id": "96888033-a15a-49e1-a594-276a55c467a5",
  "otel.status_code": "OK",
  "http.method": "POST",
  "http.status_code": 303,
  "elapsed_milliseconds": 859,
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.target": "/login"
}
{
  "msg": "[HTTP REQUEST - START]",
  "time": "2023-12-26T20:07:32.010586174Z",
  "target": "tracing_actix_web::root_span_builder",
  "line": 41,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-actix-web-0.7.6/src/root_span_builder.rs",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.route": "/admin/dashboard",
  "http.method": "GET",
  "otel.kind": "server",
  "http.scheme": "http",
  "http.target": "/admin/dashboard",
  "request_id": "4e95372c-bcbb-4510-a35a-23c2a9b969af",
  "http.client_ip": "<hidden ip>",
  "otel.name": "HTTP GET /admin/dashboard"
}
{
  "msg": "[HTTP REQUEST - EVENT] Error encountered while processing the incoming HTTP request: The user has not logged in",
  "level": 50,
  "time": "2023-12-26T20:07:32.010958773Z",
  "target": "tracing_actix_web::middleware",
  "line": 258,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-actix-web-0.7.6/src/middleware.rs",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.method": "GET",
  "exception.details": "The user has not logged in",
  "exception.message": "The user has not logged in",
  "otel.kind": "server",
  "http.client_ip": "<hidden ip>",
  "otel.name": "HTTP GET /admin/dashboard",
  "http.route": "/admin/dashboard",
  "http.scheme": "http",
  "otel.status_code": "ERROR",
  "http.target": "/admin/dashboard",
  "request_id": "4e95372c-bcbb-4510-a35a-23c2a9b969af",
  "http.status_code": 303
}
{
  "msg": "[HTTP REQUEST - END]",
  "time": "2023-12-26T20:07:32.011172073Z",
  "target": "tracing_actix_web::root_span_builder",
  "line": 41,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-actix-web-0.7.6/src/root_span_builder.rs",
  "http.flavor": "1.1",
  "http.host": "<hidden ip>:8000",
  "http.method": "GET",
  "exception.details": "The user has not logged in",
  "exception.message": "The user has not logged in",
  "otel.kind": "server",
  "elapsed_milliseconds": 0,
  "http.client_ip": "<hidden ip>",
  "otel.name": "HTTP GET /admin/dashboard",
  "http.route": "/admin/dashboard",
  "http.scheme": "http",
  "otel.status_code": "ERROR",
  "http.target": "/admin/dashboard",
  "request_id": "4e95372c-bcbb-4510-a35a-23c2a9b969af",
  "http.status_code": 303
}
{
  "msg": "[HTTP REQUEST - START]",
  "time": "2023-12-26T20:07:32.037893708Z",
  "target": "tracing_actix_web::root_span_builder",
  "line": 41,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-actix-web-0.7.6/src/root_span_builder.rs",
  "http.route": "/login",
  "request_id": "c0a23fa0-c028-431a-aa63-618641bd38df",
  "http.target": "/login",
  "http.client_ip": "<hidden ip>",
  "http.flavor": "1.1",
  "http.scheme": "http",
  "otel.kind": "server",
  "http.method": "GET",
  "otel.name": "HTTP GET /login",
  "http.host": "<hidden ip>:8000"
}
{
  "msg": "[HTTP REQUEST - END]",
  "time": "2023-12-26T20:07:32.038328407Z",
  "target": "tracing_actix_web::root_span_builder",
  "line": 41,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/tracing-actix-web-0.7.6/src/root_span_builder.rs",
  "http.route": "/login",
  "otel.status_code": "OK",
  "request_id": "c0a23fa0-c028-431a-aa63-618641bd38df",
  "http.target": "/login",
  "http.client_ip": "<hidden ip>",
  "http.flavor": "1.1",
  "http.scheme": "http",
  "otel.kind": "server",
  "http.status_code": 200,
  "elapsed_milliseconds": 0,
  "otel.name": "HTTP GET /login",
  "http.host": "<hidden ip>:8000"
}
{
  "msg": "SIGINT received; starting forced shutdown",
  "time": "2023-12-26T20:07:34.563949064Z",
  "target": "actix_server::server",
  "line": 319,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/server.rs"
}
{
  "msg": "accept thread stopped",
  "time": "2023-12-26T20:07:34.564309664Z",
  "target": "actix_server::accept",
  "line": 143,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/accept.rs"
}
{
  "msg": "shutting down idle worker",
  "time": "2023-12-26T20:07:34.564429363Z",
  "target": "actix_server::worker",
  "line": 595,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/worker.rs"
}
{
  "msg": "shutting down idle worker",
  "time": "2023-12-26T20:07:34.564502963Z",
  "target": "actix_server::worker",
  "line": 595,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/worker.rs"
}
{
  "msg": "shutting down idle worker",
  "time": "2023-12-26T20:07:34.564562663Z",
  "target": "actix_server::worker",
  "line": 595,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/worker.rs"
}
{
  "msg": "force shutdown worker, closing 1 connections",
  "time": "2023-12-26T20:07:34.564389163Z",
  "target": "actix_server::worker",
  "line": 608,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/worker.rs"
}
{
  "msg": "shutting down idle worker",
  "time": "2023-12-26T20:07:34.564630463Z",
  "target": "actix_server::worker",
  "line": 595,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/worker.rs"
}
{
  "msg": "shutting down idle worker",
  "time": "2023-12-26T20:07:34.564637463Z",
  "target": "actix_server::worker",
  "line": 595,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/worker.rs"
}
{
  "msg": "shutting down idle worker",
  "time": "2023-12-26T20:07:34.564656263Z",
  "target": "actix_server::worker",
  "line": 595,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/worker.rs"
}
{
  "msg": "shutting down idle worker",
  "time": "2023-12-26T20:07:34.565055662Z",
  "target": "actix_server::worker",
  "line": 595,
  "file": "/home/owner/.cargo/registry/src/index.crates.io-6f17d22bba15001f/actix-server-2.3.0/src/worker.rs"
}
{
  "msg": "API has exited",
  "time": "2023-12-26T20:07:34.866856328Z",
  "target": "zero2prod",
  "line": 29,
  "file": "src/main.rs"
}

I'd really appreciate any help with tracking this problem down. Conversely, if this is a problem on my end such as misconfiguration or something of this sort I'm really sorry for using an issue incorrectly.

psprojectC commented 6 months ago

I did some more playing around. I spun up the server from the main branch and looked into what gets stored into redis:

owner@DESKTOP-G91GA1P:~$ redis-cli
127.0.0.1:6379> scan 0
1) "0"
2) (empty array)
127.0.0.1:6379> get 0
(nil)
127.0.0.1:6379> scan 0
1) "0"
2) 1) "tf89q1K9FP8dmTwWE45htzgym2RLlg0SE2SywvRXVG3bUbC1LOm2UL8uYqBUvQ0Q"
127.0.0.1:6379> get tf89q1K9FP8dmTwWE45htzgym2RLlg0SE2SywvRXVG3bUbC1LOm2UL8uYqBUvQ0Q
"{\"user_id\":\"\\\"ddf8994f-d522-4659-8d02-c1d479057be6\\\"\"}"
127.0.0.1:6379> monitor
OK
1703677311.854702 [0 <hidden ip>:49076] "SET" "Xjy7LBxUABf1xbJQ1Klngl0rLt0DpEou2JFJXue2t2FmudtHOBlvAaIJg2wVxbG8" "{\"user_id\":\"\\\"ddf8994f-d522-4659-8d02-c1d479057be6\\\"\"}" "NX" "EX" "86400"

I tried to log in twice. First time was without monitoring, second time was with monitoring enabled. Maybe I'm getting something wrong, but my understanding is we use user_id to retrieve the session auth token. But in the redis itself user_id is part of JSON that gets stored against those long ass keys. And looking at the code I'm not sure which of those admin_dashboard is trying to get.

psprojectC commented 6 months ago

Hotfixed by: https://github.com/LukeMathWalker/zero-to-production/issues/234#issuecomment-1825106004 Although that's far from ideal because it makes cookies less secure