Hi Nick,
Thanks for getting in touch! From looking at your log it appears the upgrade is being performed by two different processes at the same time (you can see the PIDs in the log files) and this causes the error.
# Summary
Something unexpected is interfering with our upgrade process, causing the SQL Schema Upgrade to fail. We need to be more robust in these scenarios, and we are working on that right now.
What are we doing about it
We’re shipping a fix today which will prevent SQL Database schema upgrades from running concurrently: https://github.com/OctopusDeploy/Issues/issues/3626
We are also shipping a fix (in a few days) which will make the SQL Database schema upgrade scripts individually transactional, reducing the risk of this kind of situation from leaving your database in an inconsistent state: https://github.com/OctopusDeploy/Issues/issues/3641
I’m also going to investigate further to try and understand if there’s anything else we can do to make this process smooth.
What we need you to do
I would recommend rolling back and trying this upgrade again using 3.16.2 when it ships today.
Do you have anything special on your server which is calling Octopus.Server.exe run? Perhaps a scheduled task to keep the Octopus Service alive? If you keep reading you’ll see there’s something running as NT AUTHORITY\SYSTEM which is calling the “Octopus.Server.exe run” command that is causing our upgrade process to fail. It would be good if you could figure out what’s going on there and get back to me.
# Details
The installer shuts down the service (PID: 1604):
2017-08-09 12:46:12.2727 1604 INFO The Octopus server is shutting down...
2017-08-09 12:46:12.2727 1604 INFO Scheduler stopped successfully
2017-08-09 12:46:12.2883 1604 INFO Shutting down the embedded web server
2017-08-09 12:46:12.2883 1604 INFO listen://[::]:10943/ 1604 Listener stopped
2017-08-09 12:46:12.2883 1604 INFO The Windows Service has stopped
Then something starts the Octopus.Server.exe run command (PID: 7200) which is not good, because it’s interfering with the upgrade process:
2017-08-09 12:46:30.2887 7200 1 INFO Octopus.Server.exe version 3.16.1 (3.16.1+Branch.master.Sha.1074dc93bf810a74292a97c3432281d3c9daea3e) instance OctopusServer
2017-08-09 12:46:30.2887 7200 1 INFO Environment Information:
CurrentUser: NT AUTHORITY\SYSTEM
PID: 7200
2017-08-09 12:46:30.6637 7200 8 INFO ==== RunCommand ====
2017-08-09 12:46:33.0700 7200 8 INFO Beginning database upgrade
And when the installer completes, it runs Octopus.Server.exe service --stop (PID: 9960), which is expected, but it ends up shutting down the unexpected process which is currently performing the upgrade (PID: 7200) and this is not good:
2017-08-09 12:46:38.8045 9960 1 INFO Octopus.Server.exe version 3.16.1 (3.16.1+Branch.master.Sha.1074dc93bf810a74292a97c3432281d3c9daea3e) instance OctopusServer
2017-08-09 12:46:38.8045 9960 1 INFO Environment Information:
CurrentUser: CORP\nick.frederick
PID: 9960
2017-08-09 12:46:38.9015 9960 1 INFO ==== ServiceCommand ====
2017-08-09 12:46:38.9015 9960 1 INFO Stopping service...
2017-08-09 12:46:39.1025 7200 8 INFO Copying ServerTask data to Tmp_ServerTask table...
2017-08-09 12:46:39.2305 7200 7 INFO Stopping the Windows Service
2017-08-09 12:46:39.2305 7200 7 INFO The Octopus server is shutting down...
And then the wizard starts the next step of the upgrade, calling Octopus.Server.exe database --upgrade (PID: 10692):
2017-08-09 12:46:40.1386 9960 1 INFO Service stopped
2017-08-09 12:46:40.8506 10692 1 INFO Octopus.Server.exe version 3.16.1 (3.16.1+Branch.master.Sha.1074dc93bf810a74292a97c3432281d3c9daea3e) instance OctopusServer
2017-08-09 12:46:40.8506 10692 1 INFO Environment Information:
CurrentUser: CORP\nick.frederick
PID: 10692
2017-08-09 12:46:40.9496 10692 1 INFO ==== DatabaseCommand ====
2017-08-09 12:46:41.6216 10692 1 INFO Beginning database upgrade
2017-08-09 12:46:41.7466 10692 1 ERROR System.Data.SqlClient.SqlException (0x80131904): Invalid column name 'ServerNode'.
And this is where Octopus gets stuck in an inconsistent state.
Hope that helps!
Mike