Log with transaction failure

[ISibboI]

2024-02-19T08:04:02.1071047Z ##[group]Run echo "PASSWORD_PEPPER=test-test-test-test" >> $GITHUB_ENV
2024-02-19T08:04:02.1071744Z �[36;1mecho "PASSWORD_PEPPER=test-test-test-test" >> $GITHUB_ENV�[0m
2024-02-19T08:04:02.1072274Z �[36;1mecho "RVOC_INTEGRATION_TEST_MODE=true" >> $GITHUB_ENV�[0m
2024-02-19T08:04:02.1102345Z shell: /usr/bin/bash -e {0}
2024-02-19T08:04:02.1102640Z env:
2024-02-19T08:04:02.1103045Z   PG_DATABASE_URL: ***localhost/
2024-02-19T08:04:02.1103561Z   PG_EXAMPLE_DATABASE_URL: ***localhost/diesel_example
2024-02-19T08:04:02.1104168Z   POSTGRES_RVOC_URL: ***localhost/rvoc
2024-02-19T08:04:02.1104876Z   DETERMINATE_NIX_KVM: 0
2024-02-19T08:04:02.1105646Z   MAGIC_NIX_CACHE_DAEMONDIR: /home/runner/work/_temp/magic-nix-cache-Cw0rso
2024-02-19T08:04:02.1106467Z ##[endgroup]
2024-02-19T08:04:02.1191450Z ##[group]Run debugBinary/bin/rvoc-backend apply-migrations
2024-02-19T08:04:02.1191969Z �[36;1mdebugBinary/bin/rvoc-backend apply-migrations�[0m
2024-02-19T08:04:02.1218383Z shell: /usr/bin/bash -e {0}
2024-02-19T08:04:02.1218657Z env:
2024-02-19T08:04:02.1219292Z   PG_DATABASE_URL: ***localhost/
2024-02-19T08:04:02.1219968Z   PG_EXAMPLE_DATABASE_URL: ***localhost/diesel_example
2024-02-19T08:04:02.1220576Z   POSTGRES_RVOC_URL: ***localhost/rvoc
2024-02-19T08:04:02.1220951Z   DETERMINATE_NIX_KVM: 0
2024-02-19T08:04:02.1221372Z   MAGIC_NIX_CACHE_DAEMONDIR: /home/runner/work/_temp/magic-nix-cache-Cw0rso
2024-02-19T08:04:02.1221857Z   PASSWORD_PEPPER: test-test-test-test
2024-02-19T08:04:02.1222194Z   RVOC_INTEGRATION_TEST_MODE: true
2024-02-19T08:04:02.1222488Z ##[endgroup]
2024-02-19T08:04:02.1313388Z {"timestamp":"2024-02-19T08:04:02.131086Z","level":"INFO","fields":{"message":"Set up tracing subscriber successfully without opentelemetry"},"target":"rvoc_backend"}
2024-02-19T08:04:02.1328099Z {"timestamp":"2024-02-19T08:04:02.131558Z","level":"DEBUG","fields":{"message":"Cli arguments: ApplyMigrations"},"target":"rvoc_backend::cli","span":{"name":"run_cli_command"},"spans":[{"name":"run_cli_command"}]}
2024-02-19T08:04:02.1330297Z {"timestamp":"2024-02-19T08:04:02.131640Z","level":"DEBUG","fields":{"message":"Creating synchronous connection to database"},"target":"rvoc_backend::database::migrations","span":{"name":"apply_pending_database_migrations"},"spans":[{"name":"run_cli_command"},{"name":"apply_pending_database_migrations"}]}
2024-02-19T08:04:02.2419645Z {"timestamp":"2024-02-19T08:04:02.241202Z","level":"INFO","fields":{"message":"Executing missing database migrations"},"target":"rvoc_backend::cli","span":{"name":"apply_pending_database_migrations"},"spans":[{"name":"run_cli_command"},{"name":"apply_pending_database_migrations"}]}
2024-02-19T08:04:02.2424069Z {"timestamp":"2024-02-19T08:04:02.241321Z","level":"DEBUG","fields":{"message":"Creating synchronous connection to database"},"target":"rvoc_backend::database::migrations","span":{"name":"run_migrations"},"spans":[{"name":"run_cli_command"},{"name":"apply_pending_database_migrations"},{"name":"run_migrations"}]}
2024-02-19T08:04:02.2514903Z {"timestamp":"2024-02-19T08:04:02.251185Z","level":"INFO","fields":{"message":"Running pending database migrations (this may take a long time)..."},"target":"rvoc_backend::database::migrations","span":{"name":"run_migrations"},"spans":[{"name":"run_cli_command"},{"name":"apply_pending_database_migrations"},{"name":"run_migrations"}]}
2024-02-19T08:04:02.4299745Z {"timestamp":"2024-02-19T08:04:02.429502Z","level":"INFO","fields":{"message":"Database migrations complete"},"target":"rvoc_backend::database::migrations","span":{"name":"run_migrations"},"spans":[{"name":"run_cli_command"},{"name":"apply_pending_database_migrations"},{"name":"run_migrations"}]}
2024-02-19T08:04:02.4302352Z {"timestamp":"2024-02-19T08:04:02.429745Z","level":"INFO","fields":{"message":"Success!"},"target":"rvoc_backend::cli","span":{"name":"apply_pending_database_migrations"},"spans":[{"name":"run_cli_command"},{"name":"apply_pending_database_migrations"}]}
2024-02-19T08:04:02.4359477Z ##[group]Run debugBinary/bin/rvoc-backend run-internal-integration-tests
2024-02-19T08:04:02.4360511Z �[36;1mdebugBinary/bin/rvoc-backend run-internal-integration-tests�[0m
2024-02-19T08:04:02.4394359Z shell: /usr/bin/bash -e {0}
2024-02-19T08:04:02.4394644Z env:
2024-02-19T08:04:02.4395095Z   PG_DATABASE_URL: ***localhost/
2024-02-19T08:04:02.4395613Z   PG_EXAMPLE_DATABASE_URL: ***localhost/diesel_example
2024-02-19T08:04:02.4396146Z   POSTGRES_RVOC_URL: ***localhost/rvoc
2024-02-19T08:04:02.4396473Z   DETERMINATE_NIX_KVM: 0
2024-02-19T08:04:02.4396891Z   MAGIC_NIX_CACHE_DAEMONDIR: /home/runner/work/_temp/magic-nix-cache-Cw0rso
2024-02-19T08:04:02.4397382Z   PASSWORD_PEPPER: test-test-test-test
2024-02-19T08:04:02.4397720Z   RVOC_INTEGRATION_TEST_MODE: true
2024-02-19T08:04:02.4398021Z ##[endgroup]
2024-02-19T08:04:02.4488453Z {"timestamp":"2024-02-19T08:04:02.448581Z","level":"INFO","fields":{"message":"Set up tracing subscriber successfully without opentelemetry"},"target":"rvoc_backend"}
2024-02-19T08:04:02.4493960Z {"timestamp":"2024-02-19T08:04:02.449103Z","level":"DEBUG","fields":{"message":"Cli arguments: RunInternalIntegrationTests"},"target":"rvoc_backend::cli","span":{"name":"run_cli_command"},"spans":[{"name":"run_cli_command"}]}
2024-02-19T08:04:02.4497999Z {"timestamp":"2024-02-19T08:04:02.449227Z","level":"DEBUG","fields":{"message":"Creating synchronous connection to database"},"target":"rvoc_backend::database::migrations","span":{"name":"test_aborted_transaction"},"spans":[{"name":"run_cli_command"},{"name":"run_internal_integration_tests"},{"name":"test_aborted_transaction"}]}
2024-02-19T08:04:02.5547556Z {"timestamp":"2024-02-19T08:04:02.554372Z","level":"INFO","fields":{"message":"Test table set up successfully"},"target":"rvoc_backend::integration_tests","span":{"name":"test_aborted_transaction"},"spans":[{"name":"run_cli_command"},{"name":"run_internal_integration_tests"},{"name":"test_aborted_transaction"}]}
2024-02-19T08:04:07.6487588Z {"timestamp":"2024-02-19T08:04:07.648125Z","level":"DEBUG","fields":{"message":"temporary transaction error: could not serialize access due to read/write dependencies among transactions"},"target":"rvoc_backend::database::transactions","span":{"max_retries":0,"name":"execute_transaction"},"spans":[{"name":"run_cli_command"},{"name":"run_internal_integration_tests"},{"name":"test_aborted_transaction"},{"max_retries":0,"name":"execute_transaction"}]}
2024-02-19T08:04:07.6493444Z {"timestamp":"2024-02-19T08:04:07.648232Z","level":"ERROR","fields":{"error":"the maximum number of retries for retrying a database transaction was reached (limit: 0)"},"target":"rvoc_backend::database::transactions","span":{"max_retries":0,"name":"execute_transaction"},"spans":[{"name":"run_cli_command"},{"name":"run_internal_integration_tests"},{"name":"test_aborted_transaction"},{"max_retries":0,"name":"execute_transaction"}]}
2024-02-19T08:04:07.6498547Z {"timestamp":"2024-02-19T08:04:07.648302Z","level":"INFO","fields":{"message":"Serialisation failure should have triggered"},"target":"rvoc_backend::integration_tests","span":{"name":"test_aborted_transaction"},"spans":[{"name":"run_cli_command"},{"name":"run_internal_integration_tests"},{"name":"test_aborted_transaction"}]}
2024-02-19T08:04:07.6502101Z {"timestamp":"2024-02-19T08:04:07.648351Z","level":"INFO","fields":{"message":"First result:  Ok(())"},"target":"rvoc_backend::integration_tests","span":{"name":"test_aborted_transaction"},"spans":[{"name":"run_cli_command"},{"name":"run_internal_integration_tests"},{"name":"test_aborted_transaction"}]}
2024-02-19T08:04:07.6505450Z {"timestamp":"2024-02-19T08:04:07.648395Z","level":"INFO","fields":{"message":"Second result: Err(DatabaseTransactionRetryLimitReached { limit: 0 })"},"target":"rvoc_backend::integration_tests","span":{"name":"test_aborted_transaction"},"spans":[{"name":"run_cli_command"},{"name":"run_internal_integration_tests"},{"name":"test_aborted_transaction"}]}
2024-02-19T08:04:07.6510456Z {"timestamp":"2024-02-19T08:04:07.650484Z","level":"INFO","fields":{"message":"Success! Transactions still work after serialisation failure"},"target":"rvoc_backend::integration_tests","span":{"name":"test_aborted_transaction"},"spans":[{"name":"run_cli_command"},{"name":"run_internal_integration_tests"},{"name":"test_aborted_transaction"}]}
2024-02-19T08:04:07.6580455Z ##[group]Run BerniWittmann/background-server-action@v1
2024-02-19T08:04:07.6581174Z with:
2024-02-19T08:04:07.6581812Z   command: RUST_BACKTRACE=1 integrationTestsBinary/bin/integration-tests
2024-02-19T08:04:07.6582616Z   start: debugBinary/bin/rvoc-backend web
2024-02-19T08:04:07.6582951Z env:
2024-02-19T08:04:07.6583337Z   PG_DATABASE_URL: ***localhost/
2024-02-19T08:04:07.6583842Z   PG_EXAMPLE_DATABASE_URL: ***localhost/diesel_example
2024-02-19T08:04:07.6584372Z   POSTGRES_RVOC_URL: ***localhost/rvoc
2024-02-19T08:04:07.6584704Z   DETERMINATE_NIX_KVM: 0
2024-02-19T08:04:07.6585118Z   MAGIC_NIX_CACHE_DAEMONDIR: /home/runner/work/_temp/magic-nix-cache-Cw0rso
2024-02-19T08:04:07.6585609Z   PASSWORD_PEPPER: test-test-test-test
2024-02-19T08:04:07.6585940Z   RVOC_INTEGRATION_TEST_MODE: true
2024-02-19T08:04:07.6586236Z ##[endgroup]
2024-02-19T08:04:07.7216840Z start server "debugBinary/bin/rvoc-backend web" command "debugBinary/bin/rvoc-backend web"
2024-02-19T08:04:07.7235262Z run command "RUST_BACKTRACE=1 integrationTestsBinary/bin/integration-tests" command "RUST_BACKTRACE=1 integrationTestsBinary/bin/integration-tests"
2024-02-19T08:04:07.7262347Z [command]/usr/bin/bash -c debugBinary/bin/rvoc-backend web
2024-02-19T08:04:07.7298194Z [command]/usr/bin/bash -c RUST_BACKTRACE=1 integrationTestsBinary/bin/integration-tests
2024-02-19T08:04:07.7353431Z 08:04:07 [INFO] Logging initialised
2024-02-19T08:04:07.7358477Z {"timestamp":"2024-02-19T08:04:07.735256Z","level":"INFO","fields":{"message":"Set up tracing subscriber successfully without opentelemetry"},"target":"rvoc_backend"}
2024-02-19T08:04:07.7365125Z {"timestamp":"2024-02-19T08:04:07.735868Z","level":"DEBUG","fields":{"message":"Cli arguments: Web"},"target":"rvoc_backend::cli","span":{"name":"run_cli_command"},"spans":[{"name":"run_cli_command"}]}
2024-02-19T08:04:07.7376897Z {"timestamp":"2024-02-19T08:04:07.735958Z","level":"DEBUG","fields":{"message":"Running rvoc backend with configuration: Configuration {\n    integration_test_mode: true,\n    postgres_url: ***SECRET***,\n    opentelemetry_url: None,\n    shutdown_timeout: TimeDelta {\n        secs: 30,\n        nanos: 0,\n    },\n    job_queue_poll_interval: TimeDelta {\n        secs: 60,\n        nanos: 0,\n    },\n    maximum_transaction_retry_count: 10,\n    api_listen_address: 0.0.0.0:8093,\n    minimum_username_length: 3,\n    maximum_username_length: 50,\n    minimum_password_length: 8,\n    maximum_password_length: 100,\n    password_pepper: ***SECRET***,\n    password_argon2id_minimum_memory_kib: 19456,\n    password_argon2id_minimum_iterations: 2,\n    password_argon2id_parallelism: 1,\n    maximum_session_id_generation_retry_count: 10,\n    wiktionary_temporary_data_directory: \"data/wiktionary_data\",\n    wiktionary_dump_insertion_batch_size: 1000,\n    wiktionary_update_interval: TimeDelta {\n        secs: 86400,\n        nanos: 0,\n    },\n    delete_expired_sessions_interval: TimeDelta {\n        secs: 86400,\n        nanos: 0,\n    },\n}"},"target":"rvoc_backend::cli","span":{"name":"run_rvoc_backend"},"spans":[{"name":"run_cli_command"},{"name":"run_rvoc_backend"}]}
2024-02-19T08:04:07.7386660Z {"timestamp":"2024-02-19T08:04:07.736122Z","level":"DEBUG","fields":{"message":"Creating synchronous connection to database"},"target":"rvoc_backend::database::migrations","span":{"name":"run_rvoc_backend"},"spans":[{"name":"run_cli_command"},{"name":"run_rvoc_backend"}]}
2024-02-19T08:04:07.7515631Z {"timestamp":"2024-02-19T08:04:07.750942Z","level":"INFO","fields":{"message":"Initialising job queue"},"target":"rvoc_backend::job_queue","span":{"name":"initialise_job_queue"},"spans":[{"name":"run_cli_command"},{"name":"run_rvoc_backend"},{"shutdown_flag":"false","name":"spawn_job_queue_runner"},{"name":"initialise_job_queue"}]}
2024-02-19T08:04:07.8470463Z {"timestamp":"2024-02-19T08:04:07.846430Z","level":"INFO","fields":{"message":"Spawning job queue runner"},"target":"rvoc_backend::job_queue","span":{"shutdown_flag":"false","name":"spawn_job_queue_runner"},"spans":[{"name":"run_cli_command"},{"name":"run_rvoc_backend"},{"shutdown_flag":"false","name":"spawn_job_queue_runner"}]}
2024-02-19T08:04:07.8485275Z {"timestamp":"2024-02-19T08:04:07.846910Z","level":"INFO","fields":{"message":"Starting web API"},"target":"rvoc_backend::web","span":{"name":"run_web_api"},"spans":[{"name":"run_cli_command"},{"name":"run_rvoc_backend"},{"name":"run_web_api"}]}
2024-02-19T08:04:07.8488019Z {"timestamp":"2024-02-19T08:04:07.847661Z","level":"DEBUG","fields":{"message":"Listening for API requests on 0.0.0.0:8093"},"target":"rvoc_backend::web","span":{"name":"run_web_api"},"spans":[{"name":"run_cli_command"},{"name":"run_rvoc_backend"},{"name":"run_web_api"}]}
2024-02-19T08:04:07.8519542Z {"timestamp":"2024-02-19T08:04:07.851493Z","level":"DEBUG","fields":{"message":"Executing job InProgressJob { scheduled_time: 2024-02-19T08:04:07.843141Z, start_time: 2024-02-19T08:04:07.851044322Z, name: UpdateWiktionary }"},"target":"rvoc_backend::job_queue","span":{"name":"poll_job_queue_and_execute"},"spans":[{"name":"poll_job_queue_and_execute"}]}
2024-02-19T08:04:07.8524527Z {"timestamp":"2024-02-19T08:04:07.851750Z","level":"WARN","fields":{"message":"Not running update_wiktionary because integration_test_mode is enabled"},"target":"rvoc_backend::job_queue::jobs::update_witkionary","span":{"name":"poll_job_queue_and_execute"},"spans":[{"name":"poll_job_queue_and_execute"}]}
2024-02-19T08:04:07.8530493Z {"timestamp":"2024-02-19T08:04:07.851980Z","level":"DEBUG","fields":{"message":"Completed job UpdateWiktionary with a duration of PT0.000930567S after a start delayed by PT0.007903322S"},"target":"rvoc_backend::job_queue","span":{"job":"InProgressJob { scheduled_time: 2024-02-19T08:04:07.843141Z, start_time: 2024-02-19T08:04:07.851044322Z, name: UpdateWiktionary }","name":"complete_job"},"spans":[{"name":"poll_job_queue_and_execute"},{"job":"InProgressJob { scheduled_time: 2024-02-19T08:04:07.843141Z, start_time: 2024-02-19T08:04:07.851044322Z, name: UpdateWiktionary }","name":"complete_job"}]}
2024-02-19T08:04:11.7207846Z {"timestamp":"2024-02-19T08:04:11.719558Z","level":"ERROR","fields":{"error":"username length (74) outside of allowed range [3, 50]"},"target":"rvoc_backend::web::user","span":{"create_account":"CreateAccount { username: \"else-else-else-else-else-else-else-else-else-else-else-else-else-else-else\", password: ***SECRET*** }","name":"create_account"},"spans":[{"create_account":"CreateAccount { username: \"else-else-else-else-else-else-else-else-else-else-else-else-else-else-else\", password: ***SECRET*** }","name":"create_account"}]}
2024-02-19T08:04:11.7220862Z {"timestamp":"2024-02-19T08:04:11.719672Z","level":"ERROR","fields":{"message":"User error: UsernameLength { actual: 74, minimum: 3, maximum: 50 }"},"target":"rvoc_backend::web"}
2024-02-19T08:04:11.7225125Z {"timestamp":"2024-02-19T08:04:11.720166Z","level":"ERROR","fields":{"error":"password length (185) outside of allowed range [8, 100]"},"target":"rvoc_backend::web::user","span":{"create_account":"CreateAccount { username: \"josef\", password: ***SECRET*** }","name":"create_account"},"spans":[{"create_account":"CreateAccount { username: \"josef\", password: ***SECRET*** }","name":"create_account"}]}
2024-02-19T08:04:11.7229097Z {"timestamp":"2024-02-19T08:04:11.720257Z","level":"ERROR","fields":{"message":"User error: PasswordLength { actual: 185, minimum: 8, maximum: 100 }"},"target":"rvoc_backend::web"}
2024-02-19T08:04:11.7233191Z {"timestamp":"2024-02-19T08:04:11.720584Z","level":"ERROR","fields":{"error":"username length (2) outside of allowed range [3, 50]"},"target":"rvoc_backend::web::user","span":{"create_account":"CreateAccount { username: \"K.\", password: ***SECRET*** }","name":"create_account"},"spans":[{"create_account":"CreateAccount { username: \"K.\", password: ***SECRET*** }","name":"create_account"}]}
2024-02-19T08:04:11.7237025Z {"timestamp":"2024-02-19T08:04:11.720671Z","level":"ERROR","fields":{"message":"User error: UsernameLength { actual: 2, minimum: 3, maximum: 50 }"},"target":"rvoc_backend::web"}
2024-02-19T08:04:11.7241867Z {"timestamp":"2024-02-19T08:04:11.720994Z","level":"ERROR","fields":{"error":"password length (3) outside of allowed range [8, 100]"},"target":"rvoc_backend::web::user","span":{"create_account":"CreateAccount { username: \"hans\", password: ***SECRET*** }","name":"create_account"},"spans":[{"create_account":"CreateAccount { username: \"hans\", password: ***SECRET*** }","name":"create_account"}]}
2024-02-19T08:04:11.7245800Z {"timestamp":"2024-02-19T08:04:11.721075Z","level":"ERROR","fields":{"message":"User error: PasswordLength { actual: 3, minimum: 8, maximum: 100 }"},"target":"rvoc_backend::web"}
2024-02-19T08:04:12.8022102Z {"timestamp":"2024-02-19T08:04:12.801222Z","level":"INFO","fields":{"message":"User not found: Username { name: \"peter\" }"},"target":"rvoc_backend::web::authentication","span":{"max_retries":10,"name":"execute_transaction"},"spans":[{"login":"Login { username: \"peter\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"},{"max_retries":10,"name":"execute_transaction"}]}
2024-02-19T08:04:12.8030262Z {"timestamp":"2024-02-19T08:04:12.802169Z","level":"ERROR","fields":{"error":"the username or password did not match"},"target":"rvoc_backend::database::transactions","span":{"max_retries":10,"name":"execute_transaction"},"spans":[{"login":"Login { username: \"peter\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"},{"max_retries":10,"name":"execute_transaction"}]}
2024-02-19T08:04:12.8035108Z {"timestamp":"2024-02-19T08:04:12.802286Z","level":"ERROR","fields":{"error":"the username or password did not match"},"target":"rvoc_backend::web::authentication","span":{"login":"Login { username: \"peter\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"},"spans":[{"login":"Login { username: \"peter\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"}]}
2024-02-19T08:04:12.8037806Z {"timestamp":"2024-02-19T08:04:12.802392Z","level":"ERROR","fields":{"message":"User error: InvalidUsernamePassword"},"target":"rvoc_backend::web"}
2024-02-19T08:04:14.4845001Z {"timestamp":"2024-02-19T08:04:14.483181Z","level":"INFO","fields":{"message":"Wrong password for user: Username { name: \"lothar\" }"},"target":"rvoc_backend::web::authentication","span":{"max_retries":10,"name":"execute_transaction"},"spans":[{"login":"Login { username: \"lothar\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"},{"max_retries":10,"name":"execute_transaction"}]}
2024-02-19T08:04:14.4853833Z {"timestamp":"2024-02-19T08:04:14.484154Z","level":"ERROR","fields":{"error":"the username already exists: rosa"},"target":"rvoc_backend::database::transactions","span":{"max_retries":10,"name":"execute_transaction"},"spans":[{"create_account":"CreateAccount { username: \"rosa\", password: ***SECRET*** }","name":"create_account"},{"max_retries":10,"name":"execute_transaction"}]}
2024-02-19T08:04:14.4859755Z {"timestamp":"2024-02-19T08:04:14.484299Z","level":"ERROR","fields":{"error":"the username already exists: rosa"},"target":"rvoc_backend::web::user","span":{"create_account":"CreateAccount { username: \"rosa\", password: ***SECRET*** }","name":"create_account"},"spans":[{"create_account":"CreateAccount { username: \"rosa\", password: ***SECRET*** }","name":"create_account"}]}
2024-02-19T08:04:14.4863796Z {"timestamp":"2024-02-19T08:04:14.484367Z","level":"ERROR","fields":{"message":"User error: UsernameExists { username: \"rosa\" }"},"target":"rvoc_backend::web"}
2024-02-19T08:04:15.0445595Z {"timestamp":"2024-02-19T08:04:15.043733Z","level":"ERROR","fields":{"error":"the username or password did not match"},"target":"rvoc_backend::database::transactions","span":{"max_retries":10,"name":"execute_transaction"},"spans":[{"login":"Login { username: \"lothar\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"},{"max_retries":10,"name":"execute_transaction"}]}
2024-02-19T08:04:15.0451630Z {"timestamp":"2024-02-19T08:04:15.043876Z","level":"ERROR","fields":{"error":"the username or password did not match"},"target":"rvoc_backend::web::authentication","span":{"login":"Login { username: \"lothar\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"},"spans":[{"login":"Login { username: \"lothar\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"}]}
2024-02-19T08:04:15.0456163Z {"timestamp":"2024-02-19T08:04:15.043965Z","level":"ERROR","fields":{"message":"User error: InvalidUsernamePassword"},"target":"rvoc_backend::web"}
2024-02-19T08:04:15.0459510Z {"timestamp":"2024-02-19T08:04:15.045026Z","level":"ERROR","fields":{"error":"password length (131) outside of allowed range [8, 100]"},"target":"rvoc_backend::database::transactions","span":{"max_retries":10,"name":"execute_transaction"},"spans":[{"login":"Login { username: \"alois\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"},{"max_retries":10,"name":"execute_transaction"}]}
2024-02-19T08:04:15.0465200Z {"timestamp":"2024-02-19T08:04:15.045147Z","level":"ERROR","fields":{"error":"password length (131) outside of allowed range [8, 100]"},"target":"rvoc_backend::web::authentication","span":{"login":"Login { username: \"alois\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"},"spans":[{"login":"Login { username: \"alois\", password: ***SECRET*** }","session":"WritableSession { session: Session { state: NewUnchanged { expiry: Never, data: Anonymous } } }","name":"login"}]}
2024-02-19T08:04:15.0469120Z {"timestamp":"2024-02-19T08:04:15.045249Z","level":"ERROR","fields":{"message":"User error: PasswordLength { actual: 131, minimum: 8, maximum: 100 }"},"target":"rvoc_backend::web"}
2024-02-19T08:04:15.6125239Z {"timestamp":"2024-02-19T08:04:15.611938Z","level":"TRACE","fields":{"message":"Session id that was supposed to be deleted was not found. This may happen if the account was deleted."},"target":"rvoc_backend::web::session","span":{"max_retries":10,"name":"execute_transaction"},"spans":[{"max_retries":10,"name":"execute_transaction"}]}
2024-02-19T08:04:15.6445641Z {"timestamp":"2024-02-19T08:04:15.643881Z","level":"DEBUG","fields":{"message":"temporary transaction error: could not serialize access due to read/write dependencies among transactions"},"target":"rvoc_backend::database::transactions","span":{"max_retries":10,"name":"execute_transaction"},"spans":[{"max_retries":10,"name":"execute_transaction"}]}
2024-02-19T08:04:15.6451813Z {"timestamp":"2024-02-19T08:04:15.643992Z","level":"ERROR","fields":{"error":"permanent transaction error: Cannot perform this operation while a transaction is open"},"target":"rvoc_backend::database::transactions","span":{"max_retries":10,"name":"execute_transaction"},"spans":[{"max_retries":10,"name":"execute_transaction"}]}
2024-02-19T08:04:15.6456101Z {"timestamp":"2024-02-19T08:04:15.644062Z","level":"ERROR","fields":{"message":"Failed to store session: SessionStoreConnector(UpdateSession { source: AlreadyInTransaction })"},"target":"typed_session_axum::session"}
2024-02-19T08:04:15.6484073Z 08:04:15 [ERROR] Err(backend/integration-tests/src/main.rs:232:5
2024-02-19T08:04:15.6484693Z 
2024-02-19T08:04:15.6484835Z Caused by:
2024-02-19T08:04:15.6485299Z     unexpected response: 500 Internal Server Error
2024-02-19T08:04:15.6485931Z     expected: 204 No Content
2024-02-19T08:04:15.6486696Z     content:
2024-02-19T08:04:15.6487047Z     ""
2024-02-19T08:04:15.6487355Z     
2024-02-19T08:04:15.6487536Z 
2024-02-19T08:04:15.6487681Z Stack backtrace:
2024-02-19T08:04:15.6488149Z    0: anyhow::error::<impl anyhow::Error>::msg
2024-02-19T08:04:15.6488891Z    1: integration_tests::util::assert_response_status::{{closure}}
2024-02-19T08:04:15.6489666Z    2: integration_tests::test_wrong_password::{{closure}}
2024-02-19T08:04:15.6490392Z    3: tokio::runtime::task::core::Core<T,S>::poll::{{closure}}
2024-02-19T08:04:15.6491085Z    4: tokio::runtime::task::core::Core<T,S>::poll
2024-02-19T08:04:15.6491751Z    5: tokio::runtime::task::harness::poll_future::{{closure}}
2024-02-19T08:04:15.6492740Z    6: <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
2024-02-19T08:04:15.6493623Z    7: std::panicking::try::do_call
2024-02-19T08:04:15.6494096Z    8: __rust_try
2024-02-19T08:04:15.6494486Z    9: std::panicking::try
2024-02-19T08:04:15.6494952Z   10: std::panic::catch_unwind
2024-02-19T08:04:15.6495504Z   11: tokio::runtime::task::harness::poll_future
2024-02-19T08:04:15.6496237Z   12: tokio::runtime::task::harness::Harness<T,S>::poll_inner
2024-02-19T08:04:15.6497024Z   13: tokio::runtime::task::harness::Harness<T,S>::poll
2024-02-19T08:04:15.6497677Z   14: tokio::runtime::task::raw::poll
2024-02-19T08:04:15.6498238Z   15: tokio::runtime::task::raw::RawTask::poll
2024-02-19T08:04:15.6498861Z   16: tokio::runtime::task::LocalNotified<S>::run
2024-02-19T08:04:15.6500445Z   17: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}
2024-02-19T08:04:15.6501606Z   18: tokio::runtime::scheduler::current_thread::Context::run_task::{{closure}}
2024-02-19T08:04:15.6502555Z   19: tokio::runtime::scheduler::current_thread::Context::enter
2024-02-19T08:04:15.6503414Z   20: tokio::runtime::scheduler::current_thread::Context::run_task
2024-02-19T08:04:15.6504403Z   21: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}
2024-02-19T08:04:15.6505454Z   22: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
2024-02-19T08:04:15.6506056Z   23: tokio::runtime::context::scoped::Scoped<T>::set
2024-02-19T08:04:15.6506496Z   24: tokio::runtime::context::set_scheduler::{{closure}}
2024-02-19T08:04:15.6506902Z   25: std::thread::local::LocalKey<T>::try_with
2024-02-19T08:04:15.6507268Z   26: std::thread::local::LocalKey<T>::with
2024-02-19T08:04:15.6507624Z   27: tokio::runtime::context::set_scheduler
2024-02-19T08:04:15.6508066Z   28: tokio::runtime::scheduler::current_thread::CoreGuard::enter
2024-02-19T08:04:15.6508576Z   29: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
2024-02-19T08:04:15.6509164Z   30: tokio::runtime::scheduler::current_thread::CurrentThread::block_on::{{closure}}
2024-02-19T08:04:15.6509698Z   31: tokio::runtime::context::runtime::enter_runtime
2024-02-19T08:04:15.6510172Z   32: tokio::runtime::scheduler::current_thread::CurrentThread::block_on
2024-02-19T08:04:15.6510650Z   33: tokio::runtime::runtime::Runtime::block_on
2024-02-19T08:04:15.6511006Z   34: integration_tests::main
2024-02-19T08:04:15.6511306Z   35: core::ops::function::FnOnce::call_once
2024-02-19T08:04:15.6511723Z   36: std::sys_common::backtrace::__rust_begin_short_backtrace
2024-02-19T08:04:15.6512122Z   37: std::rt::lang_start::{{closure}}
2024-02-19T08:04:15.6512437Z   38: std::rt::lang_start_internal
2024-02-19T08:04:15.6512722Z   39: std::rt::lang_start
2024-02-19T08:04:15.6512971Z   40: main
2024-02-19T08:04:15.6513185Z   41: __libc_start_call_main
2024-02-19T08:04:15.6513461Z   42: __libc_start_main@GLIBC_2.2.5
2024-02-19T08:04:15.6513747Z   43: _start)
2024-02-19T08:04:15.6514040Z 08:04:15 [ERROR] Finished with errors in 1/11 tests
2024-02-19T08:04:15.6514415Z Error: Finished with errors
2024-02-19T08:04:15.6514610Z 
2024-02-19T08:04:15.6514697Z Stack backtrace:
2024-02-19T08:04:15.6514972Z    0: anyhow::error::<impl anyhow::Error>::msg
2024-02-19T08:04:15.6515320Z    1: anyhow::__private::format_err
2024-02-19T08:04:15.6515831Z    2: integration_tests::main::{{closure}}
2024-02-19T08:04:15.6516264Z    3: <core::pin::Pin<P> as core::future::future::Future>::poll
2024-02-19T08:04:15.6516933Z    4: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}::{{closure}}
2024-02-19T08:04:15.6517680Z    5: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}::{{closure}}
2024-02-19T08:04:15.6518275Z    6: tokio::runtime::scheduler::current_thread::Context::enter
2024-02-19T08:04:15.6518823Z    7: tokio::runtime::scheduler::current_thread::CoreGuard::block_on::{{closure}}
2024-02-19T08:04:15.6519414Z    8: tokio::runtime::scheduler::current_thread::CoreGuard::enter::{{closure}}
2024-02-19T08:04:15.6519917Z    9: tokio::runtime::context::scoped::Scoped<T>::set
2024-02-19T08:04:15.6520345Z   10: tokio::runtime::context::set_scheduler::{{closure}}
2024-02-19T08:04:15.6520756Z   11: std::thread::local::LocalKey<T>::try_with
2024-02-19T08:04:15.6521118Z   12: std::thread::local::LocalKey<T>::with
2024-02-19T08:04:15.6521476Z   13: tokio::runtime::context::set_scheduler
2024-02-19T08:04:15.6521907Z   14: tokio::runtime::scheduler::current_thread::CoreGuard::enter
2024-02-19T08:04:15.6522414Z   15: tokio::runtime::scheduler::current_thread::CoreGuard::block_on
2024-02-19T08:04:15.6522998Z   16: tokio::runtime::scheduler::current_thread::CurrentThread::block_on::{{closure}}
2024-02-19T08:04:15.6523539Z   17: tokio::runtime::context::runtime::enter_runtime
2024-02-19T08:04:15.6524144Z   18: tokio::runtime::scheduler::current_thread::CurrentThread::block_on
2024-02-19T08:04:15.6524618Z   19: tokio::runtime::runtime::Runtime::block_on
2024-02-19T08:04:15.6524968Z   20: integration_tests::main
2024-02-19T08:04:15.6525278Z   21: core::ops::function::FnOnce::call_once
2024-02-19T08:04:15.6525687Z   22: std::sys_common::backtrace::__rust_begin_short_backtrace
2024-02-19T08:04:15.6526089Z   23: std::rt::lang_start::{{closure}}
2024-02-19T08:04:15.6526406Z   24: std::rt::lang_start_internal
2024-02-19T08:04:15.6526692Z   25: std::rt::lang_start
2024-02-19T08:04:15.6526947Z   26: main
2024-02-19T08:04:15.6527174Z   27: __libc_start_call_main
2024-02-19T08:04:15.6527453Z   28: __libc_start_main@GLIBC_2.2.5
2024-02-19T08:04:15.6527746Z   29: _start
2024-02-19T08:04:15.6944121Z ##[error]The process '/usr/bin/bash' failed with exit code 1
2024-02-19T08:04:15.7020780Z Post job cleanup.
2024-02-19T08:04:15.7835263Z   �[2m2024-02-19T08:04:15.781293Z�[0m �[32m INFO�[0m �[1;32mmagic_nix_cache::api�[0m�[32m: �[32mWorkflow finished�[0m
2024-02-19T08:04:15.7836986Z     �[2;3mat�[0m magic-nix-cache/src/api.rs:50
2024-02-19T08:04:15.7837763Z 
2024-02-19T08:04:15.7886260Z   �[2m2024-02-19T08:04:15.788083Z�[0m �[32m INFO�[0m �[1;32mmagic_nix_cache::api�[0m�[32m: �[32mPushing 1046 new paths�[0m
2024-02-19T08:04:15.7887735Z     �[2;3mat�[0m magic-nix-cache/src/api.rs:59
2024-02-19T08:04:15.7888442Z