"Applied:" is logged when migration fails

[bryfox]

Description

If a migration results in an error, then log output still contains "Applied:" prior to the error.

https://github.com/amacneil/dbmate/blob/fb55683a63f1990a610c798619966576320c5844/pkg/dbmate/db.go#L410-L414

Is this intentional? I would expect "Applied:" to be logged only if everything succeeded and the version record was inserted.

[dossy]

I don't know if this is intentional, and I can definitely understand how "Applied:" implies success, but in this case it's just a landmark to let the user know which migration was just performed regardless of its success or failure status.

This way, in the case of an error, it's clear which migration the error refers to, which would be the most recently emitted "Applied:" migration.

I can see how this may be confusing, but this alleviates the need to ensure all error messages include the migration information by emitting it before any error messages and simplifies the code.

If the code were changed to not emit the "Applied:" line when a migration does not apply successfully, how much work will there be to ensure the error message clearly identifies which migration caused the error?

[bryfox]

I'd have thought the "Applying" entry was enough to identify the migration that produced the error, and also reads more like a log of what happened; for example:

Applying: 20151127184807_create_users_table.sql
Applied: 20151127184807_create_users_table.sql in 123µs
Applying: 20250101000000_some_new_migration.sql
Error: ...

[dossy]

I suppose the only useful reason to emit the "Applied:" line in the case of an error is to help distinguish between errors during migration file parsing vs. migration query execution:

https://github.com/amacneil/dbmate/blob/fb55683a63f1990a610c798619966576320c5844/pkg/dbmate/db.go#L377-L385

If the "Applied:" line is present, then the error is due to migration query execution. If the "Applied:" line is absent, then the error occurred during migration file parsing.

This probably isn't an incredibly valuable distinction, but if anyone is parsing the dbmate execution output (e.g., in a CI pipeline) and is relying on this distinction to be able to detect the difference, then changing this behavior would break their use case.

[bryfox]

This probably isn't an incredibly valuable distinction, but if anyone is parsing the dbmate execution output (e.g., in a CI pipeline) and is relying on this distinction to be able to detect the difference, then changing this behavior would break their use case.

True; parsing errors should be pretty clear from the message, but anything I'd want to suggest here would be breaking in that way. Shall I close this issue, or keep it around as an idea for a future version with breaking changes?

[dossy]

I think leaving it open for some time, like 90 days, to see if anyone else chimes in, either in support for or in opposition to the idea, before deciding how to proceed would be reasonable.

[bbstilson]

I just hit this error. It is confusing and ideally would be changed.

What I think is happening (without reading the code) is:

1. BEGIN;
2. "Applying: 20251009175255_foo.sql"
3. run migration:up
4. "Applied: 20251009175255_foo.sql"
5. COMMIT; -- error happens here

but what should happen is

1. "Applying: 20251009175255_foo.sql"
2. BEGIN;
3. run migration:up
4. COMMIT; -- error happens here