Core breaks after upgrade to 10.0.0

Question

After upgrading both Horizon and Core to new stable versions, I can no longer get stellar-core to start.

before:

ENV STELLAR_CORE_VERSION 9.2.0-551-7561c1d5
ENV HORIZON_VERSION 0.13.1

after:

ENV STELLAR_CORE_VERSION 10.0.0-685-1fc018b4
ENV HORIZON_VERSION 0.14.0

The issue:

stellard            | 2018-09-12 02:21:19,559 INFO exited: stellar-core (exit status 1; not expected)
stellard            | 2018-09-12 02:21:20,541 INFO spawned: 'stellar-core' with pid 88
stellard            | 2018-09-12 02:21:20,619 INFO exited: stellar-core (exit status 1; not expected)
stellard            | 2018-09-12 02:21:22,538 INFO spawned: 'stellar-core' with pid 111
stellard            | 2018-09-12 02:21:22,615 INFO exited: stellar-core (exit status 1; not expected)
stellard            | 2018-09-12 02:21:25,541 INFO spawned: 'stellar-core' with pid 132
stellard            | 2018-09-12 02:21:25,641 INFO exited: stellar-core (exit status 1; not expected)
stellard            | 2018-09-12 02:21:29,541 INFO spawned: 'stellar-core' with pid 151
stellard            | 2018-09-12 02:21:29,638 INFO exited: stellar-core (exit status 1; not expected)
stellard            | 2018-09-12 02:21:30,539 INFO gave up: stellar-core entered FATAL state, too many start retries too quickly 

From supervisorctl:

horizon                          RUNNING   pid 21, uptime 0:00:15
postgresql                       RUNNING   pid 19, uptime 0:00:15
stellar-core                     FATAL     Exited too quickly (process log may have details)
supervisor> tail stellar-core
cation destructing
2018-09-12T02:21:25.639 GCHFW [default INFO] Application destroyed
starting core...
2018-09-12T02:21:29.617 <startup> [default INFO] Assigning calculated value of 1 to FAILURE_SAFETY
2018-09-12T02:21:29.620 GAUTY [default INFO] Starting stellar-core v10.0.0
2018-09-12T02:21:29.620 GAUTY [default INFO] Config from /opt/stellar/core/etc/stellar-core.cfg
2018-09-12T02:21:29.620 GAUTY [Database INFO] Connecting to: postgresql://dbname=core host=localhost user=stellar password=********
2018-09-12T02:21:29.626 GAUTY [SCP INFO] LocalNode::LocalNode@GAUTY qSet: ba2fc8
2018-09-12T02:21:29.626 GAUTY [default INFO] Listening on 0.0.0.0:11626 for HTTP requests
2018-09-12T02:21:29.627 GAUTY [History INFO] Archive 'cache' has 'get' command only, will not be written
2018-09-12T02:21:29.627 GAUTY [History INFO] Archive 'sdf1' has 'get' command only, will not be written
2018-09-12T02:21:29.627 GAUTY [History INFO] Archive 'sdf2' has 'get' command only, will not be written
2018-09-12T02:21:29.627 GAUTY [History INFO] Archive 'sdf3' has 'get' command only, will not be written
2018-09-12T02:21:29.627 GAUTY [History WARNING] No writable archives configured, history will not be written.
2018-09-12T02:21:29.627 GAUTY [Database INFO] Applying DB schema upgrade to version 7
2018-09-12T02:21:29.636 GAUTY [default FATAL] Got an exception: Cannot execute query. ERROR:  column "buyingliabilities" of relation "accounts" already exists
 [main.cpp:671]
2018-09-12T02:21:29.636 GAUTY [default INFO] Application destructing
2018-09-12T02:21:29.636 GAUTY [default INFO] Application destroyed

supervisor> tail postgresql

supervisor> tail horizon
Waiting for postgres to be available...
starting horizon...

My config is nearly identical to the example config provided in the official git repo with a few tweaks: https://github.com/stellar/docker-stellar-core-horizon/blob/master/pubnet/core/etc/stellar-core.cfg

custom config elements:

CATCHUP_COMPLETE=true
# MAX_CONCURRENT_SUBPROCESSES (integer) default 16
# History catchup can potentialy spawn a bunch of sub-processes.
# This limits the number that will be active at a time.
MAX_CONCURRENT_SUBPROCESSES=24

# TARGET_PEER_CONNECTIONS (Integer) default 8
# This controls how aggressively the server will connect to other peers.
# It will send outbound connection attempts until it is at this
#   number of peer connections.
TARGET_PEER_CONNECTIONS=8

I use CATCHUP_COMPLETE=true to have the full history. A full resync from scratch of 310GB would be a painful experience.

Is there any way to get this back up and running without a resync? Did something major change from version 9.2.0 to 10.0.0?

Answer 1

This is a bug.

Nothing changed on that front, 10.0.0 happens to perform a schema upgrade the same way we've done it before.

I opened https://github.com/stellar/stellar-core/issues/1791 with a workaround that should get you back in business.

If you could add some details to that issue with details that could help pinpoint the root cause, it would be great. In particular, we would be interested to know what failed the very first time it tried to upgrade to that schema version 7 (that should be in the logs, very first occurrence of Applying DB schema upgrade to version 7). Also, information on your environment/context would be useful (like were you running Horizon at the time when you were upgrading core?).