Exit code 3 after adding Diesel postgres fairing

[nathanmerrill]

Description

I'm attempting to build a rocket app backed by a Diesel Postgres database. However, when I attempt to run the application, it immediately dies:

    Finished dev [unoptimized + debuginfo] target(s) in 0.56s
     Running `target\debug\sample.exe`
error: process didn't exit successfully: `target\debug\sample.exe` (exit code: 3)

To Reproduce

Cargo.toml

[dependencies]
rocket = "0.5.0-rc.1"
diesel = { version = "1.4.8", features = ["postgres"] }
rocket_sync_db_pools = { version = "0.1.0-rc.1", features = ["diesel_postgres_pool"]}

Rocket.toml

[global.databases.sample]
url = "postgres://user:password@localhost/sample"

main.rs

use rocket_sync_db_pools::{database, diesel};
#[macro_use] extern crate rocket;

#[get("/")]
fn index() -> &'static str {
    "Hello, world!"
}

#[launch]
fn rocket() -> _ {
    rocket::build()
        .mount("/", routes![index])
        .attach(MainDbConn::fairing())
}

#[database("sample")]
struct MainDbConn(diesel::PgConnection);

The application works if I remove the attach() line. I've also tested the database connection string via diesel cmdline, which works.

Expected Behavior

I'd expect either no error, or a more descriptive error than "Exit code 3".

Environment:

• OS: Windows 10
• Rocket Version: 0.5.0-rc.1

[leonbohn]

For me on Arch the code is working as-is. Have you verified that the postgresql server is actually running and the configuration for the database connection is correct? However I totally agree that the error should be more descriptive than exit code 3.

[nathanmerrill]

I've manually run the diesel CLI: diesel migration run --database-url postgres://user:password@localhost/sample, and it has successfully created tables in the database.

So, perhaps there is a difference in URL formatting between the two, or some other connection issue that doesn't present itself via cmdline, but I know at least that the postgres database is up and running.

[nathanmerrill]

Ok, I've done some additional testing, and it feels like a race issue. I've had launchoff a couple of times, but when it happens feels inconsistent. I've rebooted, restarted the postgres service, and sometimes that fixes it, sometimes it doesn't. There doesn't appear to be a rhyme or reason to it that I can tell yet.

[SergioBenitez]

Is this all of the log information you get? Try running with ROCKET_LOG_LEVEL=debug, perhaps diesel will give you more information.

Nevertheless, this is a problem with Diesel/Windows/Configuration, not Rocket.

[nathanmerrill]

I've tested it with debug logging, and there are no additional logs. Just an immediate exit code of 3, and nothing else.

I'm not really sure where the issue lies. It definitely occurs during the fairing(), but it is proving tough to debug. It feels like std::process::exit(), but even putting a breakpoint there doesn't catch the exit. I do agree, this doesn't feel like Rocket (unless there's some multithreading stuff going on at this point in time)

[MCHSL]

Same setup, if I run it under a debugger I can see the following error is written to the console before the program panics and exits:

Error: database pool init error for pool named `users_db`
   >> timed out waiting for connection
Error: Rocket failed to launch due to failing fairings:
   >> 'users_db' Database Pool

That error appears in r2d2. Judging from the code there should have been something more after that message.

[shmeeps]

I'm able to re-produce this with Postgres running on a Windows 10 machine as well. I set up a new Rocket project just to remove anything extraneous and ended up with a similar example to the OP.

Postgres logs had the following

2021-11-01 00:02:11.499 CDT [9380] LOG:  connection received: host=127.0.0.1 port=1335
2021-11-01 00:02:11.510 CDT [9380] LOG:  connection authenticated: identity="postgres" method=scram-sha-256 (C:/Program Files/PostgreSQL/14/data/pg_hba.conf:87)
2021-11-01 00:02:11.510 CDT [9380] LOG:  connection authorized: user=postgres database=postgres
2021-11-01 00:02:11.512 CDT [9380] LOG:  execute <unnamed>: SET TIME ZONE 'UTC'
2021-11-01 00:02:11.513 CDT [9380] LOG:  execute <unnamed>: SET CLIENT_ENCODING TO 'UTF8'
2021-11-01 00:02:11.611 CDT [18848] LOG:  connection received: host=127.0.0.1 port=1336
2021-11-01 00:02:11.621 CDT [18848] LOG:  connection authenticated: identity="postgres" method=scram-sha-256 (C:/Program Files/PostgreSQL/14/data/pg_hba.conf:87)
2021-11-01 00:02:11.621 CDT [18848] LOG:  connection authorized: user=postgres database=postgres
2021-11-01 00:02:11.624 CDT [18848] LOG:  execute <unnamed>: SET TIME ZONE 'UTC'
2021-11-01 00:02:11.625 CDT [18848] LOG:  execute <unnamed>: SET CLIENT_ENCODING TO 'UTF8'
2021-11-01 00:02:11.644 CDT [252] LOG:  connection received: host=127.0.0.1 port=1337
2021-11-01 00:02:11.646 CDT [14028] LOG:  connection received: host=127.0.0.1 port=1338
2021-11-01 00:02:11.655 CDT [252] LOG:  connection authenticated: identity="postgres" method=scram-sha-256 (C:/Program Files/PostgreSQL/14/data/pg_hba.conf:87)
2021-11-01 00:02:11.655 CDT [252] LOG:  connection authorized: user=postgres database=postgres
2021-11-01 00:02:11.656 CDT [14028] LOG:  connection authenticated: identity="postgres" method=scram-sha-256 (C:/Program Files/PostgreSQL/14/data/pg_hba.conf:87)
2021-11-01 00:02:11.656 CDT [14028] LOG:  connection authorized: user=postgres database=postgres
2021-11-01 00:02:11.657 CDT [252] LOG:  execute <unnamed>: SET TIME ZONE 'UTC'
2021-11-01 00:02:11.658 CDT [252] LOG:  execute <unnamed>: SET CLIENT_ENCODING TO 'UTF8'
2021-11-01 00:02:11.658 CDT [14028] LOG:  execute <unnamed>: SET TIME ZONE 'UTC'
2021-11-01 00:02:11.659 CDT [14028] LOG:  execute <unnamed>: SET CLIENT_ENCODING TO 'UTF8'
2021-11-01 00:02:11.681 CDT [22260] LOG:  connection received: host=127.0.0.1 port=1339
2021-11-01 00:02:11.683 CDT [11924] LOG:  connection received: host=127.0.0.1 port=1340
2021-11-01 00:02:12.056 CDT [252] LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.
2021-11-01 00:02:12.056 CDT [11924] LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.
2021-11-01 00:02:12.056 CDT [252] LOG:  disconnection: session time: 0:00:00.419 user=postgres database=postgres host=127.0.0.1 port=1337
2021-11-01 00:02:12.056 CDT [9380] LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.
2021-11-01 00:02:12.056 CDT [18848] LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.
2021-11-01 00:02:12.056 CDT [22260] LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.
2021-11-01 00:02:12.056 CDT [14028] LOG:  could not receive data from client: An existing connection was forcibly closed by the remote host.
2021-11-01 00:02:12.056 CDT [9380] LOG:  disconnection: session time: 0:00:00.563 user=postgres database=postgres host=127.0.0.1 port=1335
2021-11-01 00:02:12.056 CDT [14028] LOG:  disconnection: session time: 0:00:00.418 user=postgres database=postgres host=127.0.0.1 port=1338
2021-11-01 00:02:12.056 CDT [18848] LOG:  disconnection: session time: 0:00:00.451 user=postgres database=postgres host=127.0.0.1 port=1336

Which seems to indicate that the pool is disconnecting before all the connections have been established. Increasing my timeout setting doesn't change anything, so it appears that something is acting as if it detected an error. It could be that the pool manager has a bug, or it could be that my Postgres instance acts weird processing that many simultaneous connections. Either way, I would agree this is likely an issue with diesel-r2d2 or r2d2, not anything within Rocket.

I only rarely use this machine for development, so simply limiting pool_size to 2-3 stops the issue from persisting and works well enough.

[AcrylicShrimp]

I reported it on diesel-rs/diesel#2947.

[weiznich]

Diesel maintainer here.

This seems to be an platform specific issue either in diesel or in libpq. Neither r2d2 nor rocket is needed to reproduce this. See diesel-rs/diesel#2947 for details.

As I do not have a windows 10 machine for development it would be really helpful to get some help tracking down this issue from the people affected by this. See the linked thread for details about information we are looking for, maybe you can help tracking down this issue.

[SergioBenitez]

It looks like there's a platform solution at diesel-rs/diesel#2947 (comment). Since there isn't anything to fix in Rocket, I'm closing this out.

[Adimac93]

Same issue with actix and diesel::r2d2

[rustytechno]

I came across this similar error while working with Actix-Diesel-Postgres

I re-started the postgres services from services.msc(windows10)

[rustytechno]

Quick question, how to gracefully shutdown, actix server and close any postgres connections still open ?