On a newly configured server without IIS, when running with a binding on port 80 the application reports an internal error 503 when hitting it, but configuring a binding with ANY other port, the application works and behaves perfectly. The problem is our previous Octopus 2.6.x instance is working on port 80 on another host and we don’t want to have to handle a special case of port 81/8080 or whatever for this new host, since we are intending to migrate over to it completely once we have Octopus 3.x functional.
Hi Ethan,
Could you send through the Octopus Server logs (in C:\Octopus\Logs by default) as this should give us some more information about why it is failing to run on port 80.
Could you also run the following in a command prompt netstat -ano
and see if there is anything else on that server that is using port 80?
Thank you and best regards,
Henrik
The interesting thing is that it’s not actually failing to run, the service
runs just fine when I specify a port 80 binding, it is simply inaccessible
from the machine where octopus server is installed or from other machines
on the network. When they attempt to access it they get the 503 server
error.
I’ll see about attaching the logs tomorrow when I’m back in the office.
Hi Ethan,
How did you configure the binding in the Octopus Server manager? E.g. did you add it as http://localhost:80?
Thanks,
Henrik
Yeah, all my changes have been through the Octopus Server Manager. During
the default installation it used localhost:80 which didn’t work. I tried
adding the DNS names and the actual hostname but only if I don’t use port
80 will it work.
This is an early log after the reinstall while testing. The cd.deploy is the DNS name we’ve given it.
2016-12-29 10:32:08.1035 1 INFO ==== Configure command starting ====
2016-12-29 10:32:08.1896 1 INFO Web force SSL: False
2016-12-29 10:32:08.2196 1 INFO ==== Configure command completed ====
2016-12-29 10:32:10.2898 1 INFO ==== Configure command starting ====
2016-12-29 10:32:10.3198 1 INFO Web listen prefixes: http://localhost:8002/,http://cd.deploy.beta.cd.it.app/
2016-12-29 10:32:10.3488 1 INFO ==== Configure command completed ====
2016-12-29 10:32:11.8669 1 INFO Stopping service…
2016-12-29 10:32:12.1779 22 INFO Stopping the Windows Service
2016-12-29 10:32:12.1939 22 INFO The Octopus server is shutting down…
2016-12-29 10:32:12.1939 22 INFO Shutting down the embedded web server
2016-12-29 10:32:12.2409 22 INFO listen://[::]:10943/ 22 Listener stopped
2016-12-29 10:32:12.2629 22 INFO The Windows Service has stopped
2016-12-29 10:32:12.4860 1 INFO Waiting for service to become Stopped. Current status: Stopped
2016-12-29 10:32:12.7950 1 INFO Service stopped
2016-12-29 10:32:14.2251 1 INFO Waiting for service to start. Current status: StartPending
2016-12-29 10:32:14.5352 1 INFO Waiting for service to start. Current status: Running
2016-12-29 10:32:14.8432 1 INFO Service started
2016-12-29 10:32:16.2423 7 INFO Listening for HTTP requests on:
http://localhost:8002/
http://cd.deploy.beta.cd.it.app:80/
2016-12-29 10:32:16.2423 7 INFO The Octopus server is starting: Initializing database and performing migrations…
2016-12-29 10:32:16.3053 7 INFO Fetching list of already executed scripts.
2016-12-29 10:32:16.3353 7 INFO Beginning database upgrade
2016-12-29 10:32:16.3353 7 INFO Fetching list of already executed scripts.
2016-12-29 10:32:16.3614 7 INFO No new scripts need to be executed - completing.
2016-12-29 10:32:16.3803 7 INFO Beginning database upgrade
2016-12-29 10:32:16.4114 7 INFO Executing SQL Server script 'Octopus.Core.UpgradeScriptsRepeatable.Script0000 - Refresh Views.sql’
2016-12-29 10:32:16.5083 7 INFO Upgrade successful
2016-12-29 10:32:17.0504 7 INFO The Octopus server is starting: initializing extensions…
2016-12-29 10:32:17.1024 7 INFO Authentication provider Active Directory is enabled
2016-12-29 10:32:17.1224 7 INFO The Octopus server is starting: Starting message distributor…
2016-12-29 10:32:17.2394 7 INFO listen://[::]:10943/ 7 Listener started
2016-12-29 10:32:17.2694 7 INFO The Octopus server is starting: Starting task scheduler…
2016-12-29 10:32:17.7885 7 INFO The Octopus server is starting: Starting task queue…
2016-12-29 10:32:17.8375 7 INFO Web server is ready to process requests
2016-12-29 10:32:17.8655 7 INFO The Windows Service has started
2016-12-29 10:32:23.0130 13 INFO Running community library step templates sync…
2016-12-29 10:33:07.0551 1 INFO Stopping service…
2016-12-29 10:33:07.3792 6 INFO Stopping the Windows Service
2016-12-29 10:33:07.3982 6 INFO The Octopus server is shutting down…
2016-12-29 10:33:07.4162 6 INFO Shutting down the embedded web server
2016-12-29 10:33:07.4512 6 INFO listen://[::]:10943/ 6 Listener stopped
2016-12-29 10:33:07.4842 6 INFO The Windows Service has stopped
2016-12-29 10:33:07.6842 1 INFO Waiting for service to become Stopped. Current status: Stopped
2016-12-29 10:33:08.0023 1 INFO Service stopped
2016-12-29 10:33:26.2380 1 INFO Waiting for service to start. Current status: StartPending
2016-12-29 10:33:26.5550 1 INFO Waiting for service to start. Current status: Running
2016-12-29 10:33:26.8730 1 INFO Service started
2016-12-29 10:33:28.5582 7 INFO Listening for HTTP requests on:
http://localhost:8002/
http://cd.deploy.beta.cd.it.app:80/
2016-12-29 10:33:28.5752 7 INFO The Octopus server is starting: Initializing database and performing migrations…
2016-12-29 10:33:28.6412 7 INFO Fetching list of already executed scripts.
2016-12-29 10:33:28.6802 7 INFO Beginning database upgrade
2016-12-29 10:33:28.6982 7 INFO Fetching list of already executed scripts.
2016-12-29 10:33:28.7222 7 INFO No new scripts need to be executed - completing.
2016-12-29 10:33:28.7452 7 INFO Beginning database upgrade
2016-12-29 10:33:28.7882 7 INFO Executing SQL Server script 'Octopus.Core.UpgradeScriptsRepeatable.Script0000 - Refresh Views.sql’
2016-12-29 10:33:28.8902 7 INFO Upgrade successful
2016-12-29 10:33:29.5033 7 INFO The Octopus server is starting: initializing extensions…
2016-12-29 10:33:29.5653 7 INFO Authentication provider Active Directory is enabled
2016-12-29 10:33:29.5943 7 INFO The Octopus server is starting: Starting message distributor…
2016-12-29 10:33:29.7183 7 INFO listen://[::]:10943/ 7 Listener started
2016-12-29 10:33:29.7563 7 INFO The Octopus server is starting: Starting task scheduler…
2016-12-29 10:33:30.2904 7 INFO The Octopus server is starting: Starting task queue…
2016-12-29 10:33:30.3494 7 INFO Web server is ready to process requests
2016-12-29 10:33:30.3924 7 INFO The Windows Service has started
2016-12-29 10:33:35.6029 13 INFO Running community library step templates sync…
2016-12-29 10:34:02.8665 1 INFO Stopping service…
2016-12-29 10:34:03.1935 5 INFO Stopping the Windows Service
2016-12-29 10:34:03.2195 5 INFO The Octopus server is shutting down…
2016-12-29 10:34:03.2425 5 INFO Shutting down the embedded web server
2016-12-29 10:34:03.2816 5 INFO listen://[::]:10943/ 5 Listener stopped
2016-12-29 10:34:03.3145 5 INFO The Windows Service has stopped
2016-12-29 10:34:03.4996 1 INFO Waiting for service to become Stopped. Current status: Stopped
2016-12-29 10:34:03.8196 1 INFO Service stopped
2016-12-29 10:34:23.4628 1 INFO Waiting for service to start. Current status: StartPending
2016-12-29 10:34:23.7809 1 INFO Waiting for service to start. Current status: Running
2016-12-29 10:34:24.1009 1 INFO Service started
2016-12-29 10:34:25.4820 7 INFO Listening for HTTP requests on:
http://localhost:8002/
http://cd.deploy.beta.cd.it.app:80/
2016-12-29 10:34:25.4990 7 INFO The Octopus server is starting: Initializing database and performing migrations…
2016-12-29 10:34:25.5600 7 INFO Fetching list of already executed scripts.
2016-12-29 10:34:25.6000 7 INFO Beginning database upgrade
2016-12-29 10:34:25.6180 7 INFO Fetching list of already executed scripts.
2016-12-29 10:34:25.6421 7 INFO No new scripts need to be executed - completing.
2016-12-29 10:34:25.6661 7 INFO Beginning database upgrade
2016-12-29 10:34:25.7061 7 INFO Executing SQL Server script 'Octopus.Core.UpgradeScriptsRepeatable.Script0000 - Refresh Views.sql’
2016-12-29 10:34:25.8131 7 INFO Upgrade successful
2016-12-29 10:34:26.3671 7 INFO The Octopus server is starting: initializing extensions…
2016-12-29 10:34:26.4271 7 INFO Authentication provider Active Directory is enabled
2016-12-29 10:34:26.4541 7 INFO The Octopus server is starting: Starting message distributor…
2016-12-29 10:34:26.5911 7 INFO listen://[::]:10943/ 7 Listener started
2016-12-29 10:34:26.6291 7 INFO The Octopus server is starting: Starting task scheduler…
2016-12-29 10:34:27.1533 7 INFO The Octopus server is starting: Starting task queue…
2016-12-29 10:34:27.2132 7 INFO Web server is ready to process requests
2016-12-29 10:34:27.2622 7 INFO The Windows Service has started
2016-12-29 10:34:32.2657 9 INFO The last SyncCommunityActionTemplates task finished only recently; waiting a little while before running again.
2016-12-29 10:34:57.4039 9 INFO The last health check for the machine policy Default Machine Policy finished only recently; waiting a little while before running again.
2016-12-29 10:35:27.5926 15 INFO Running System Integrity Check
2016-12-29 10:35:27.8738 15 INFO Completed System Integrity Check. Overall Result: Passed
2016-12-29 13:05:35.3578 1 INFO ==== Configure command starting ====
2016-12-29 13:05:35.4360 1 INFO Web force SSL: False
2016-12-29 13:05:35.4828 1 INFO ==== Configure command completed ====
2016-12-29 13:05:37.4673 1 INFO ==== Configure command starting ====
2016-12-29 13:05:37.5142 1 INFO Web listen prefixes: http://cd.deploy.beta.cd.it.app/
2016-12-29 13:05:37.5611 1 INFO ==== Configure command completed ====
2016-12-29 13:05:38.9205 1 INFO Stopping service…
2016-12-29 13:05:39.2486 43 INFO Stopping the Windows Service
2016-12-29 13:05:39.2642 43 INFO The Octopus server is shutting down…
2016-12-29 13:05:39.2799 1 INFO Waiting for service to become Stopped. Current status: StopPending
2016-12-29 13:05:39.2955 43 INFO Shutting down the embedded web server
2016-12-29 13:05:39.3580 43 INFO listen://[::]:10943/ 43 Listener stopped
2016-12-29 13:05:39.3892 43 INFO The Windows Service has stopped
2016-12-29 13:05:39.6080 1 INFO Waiting for service to become Stopped. Current status: Stopped
2016-12-29 13:05:39.9362 1 INFO Service stopped
2016-12-29 13:05:41.2956 1 INFO Waiting for service to start. Current status: StartPending
2016-12-29 13:05:41.6237 1 INFO Waiting for service to start. Current status: Running
2016-12-29 13:05:41.9519 1 INFO Service started
2016-12-29 13:05:43.3425 7 INFO Listening for HTTP requests on:
http://cd.deploy.beta.cd.it.app:80/
2016-12-29 13:05:43.3582 7 INFO The Octopus server is starting: Initializing database and performing migrations…
2016-12-29 13:05:43.4207 7 INFO Fetching list of already executed scripts.
2016-12-29 13:05:43.4519 7 INFO Beginning database upgrade
2016-12-29 13:05:43.4675 7 INFO Fetching list of already executed scripts.
2016-12-29 13:05:43.4988 7 INFO No new scripts need to be executed - completing.
2016-12-29 13:05:43.5300 7 INFO Beginning database upgrade
2016-12-29 13:05:43.5769 7 INFO Executing SQL Server script 'Octopus.Core.UpgradeScriptsRepeatable.Script0000 - Refresh Views.sql’
2016-12-29 13:05:43.6863 7 INFO Upgrade successful
2016-12-29 13:05:44.2176 7 INFO The Octopus server is starting: initializing extensions…
2016-12-29 13:05:44.2645 7 INFO Authentication provider Active Directory is enabled
2016-12-29 13:05:44.2958 7 INFO The Octopus server is starting: Starting message distributor…
2016-12-29 13:05:44.4051 7 INFO listen://[::]:10943/ 7 Listener started
2016-12-29 13:05:44.4364 7 INFO The Octopus server is starting: Starting task scheduler…
2016-12-29 13:05:44.9207 7 INFO The Octopus server is starting: Starting task queue…
2016-12-29 13:05:44.9832 7 INFO Web server is ready to process requests
2016-12-29 13:05:44.9988 7 INFO The Windows Service has started
2016-12-29 13:05:50.1553 13 INFO Running community library step templates sync…
2016-12-29 13:06:17.1895 1 INFO ==== Configure command starting ====
2016-12-29 13:06:17.2832 1 INFO Web force SSL: False
2016-12-29 13:06:17.3301 1 INFO ==== Configure command completed ====
2016-12-29 13:06:19.3458 1 INFO ==== Configure command starting ====
2016-12-29 13:06:19.3927 1 INFO Web listen prefixes: http://cd.deploy.beta.cd.it.app/,http://cd.deploy.beta.cd.it.app:81/
2016-12-29 13:06:19.4240 1 INFO ==== Configure command completed ====
2016-12-29 13:06:20.9709 1 INFO Stopping service…
2016-12-29 13:06:21.2991 6 INFO Stopping the Windows Service
2016-12-29 13:06:21.3303 6 INFO The Octopus server is shutting down…
2016-12-29 13:06:21.3459 6 INFO Shutting down the embedded web server
2016-12-29 13:06:21.3772 6 INFO listen://[::]:10943/ 6 Listener stopped
2016-12-29 13:06:21.4084 6 INFO The Windows Service has stopped
2016-12-29 13:06:21.6272 1 INFO Waiting for service to become Stopped. Current status: Stopped
2016-12-29 13:06:21.9553 1 INFO Service stopped
2016-12-29 13:06:23.2679 1 INFO Waiting for service to start. Current status: StartPending
2016-12-29 13:06:23.6116 1 INFO Waiting for service to start. Current status: Running
2016-12-29 13:06:23.9398 1 INFO Service started
2016-12-29 13:06:25.2054 7 INFO Listening for HTTP requests on:
http://cd.deploy.beta.cd.it.app:80/
http://cd.deploy.beta.cd.it.app:81/
2016-12-29 13:06:25.2211 7 INFO The Octopus server is starting: Initializing database and performing migrations…
2016-12-29 13:06:25.2836 7 INFO Fetching list of already executed scripts.
2016-12-29 13:06:25.3148 7 INFO Beginning database upgrade
2016-12-29 13:06:25.3461 7 INFO Fetching list of already executed scripts.
2016-12-29 13:06:25.3617 7 INFO No new scripts need to be executed - completing.
2016-12-29 13:06:25.3929 7 INFO Beginning database upgrade
2016-12-29 13:06:25.4242 7 INFO Executing SQL Server script 'Octopus.Core.UpgradeScriptsRepeatable.Script0000 - Refresh Views.sql’
2016-12-29 13:06:25.5336 7 INFO Upgrade successful
2016-12-29 13:06:26.0492 7 INFO The Octopus server is starting: initializing extensions…
2016-12-29 13:06:26.1117 7 INFO Authentication provider Active Directory is enabled
2016-12-29 13:06:26.1430 7 INFO The Octopus server is starting: Starting message distributor…
2016-12-29 13:06:26.2524 7 INFO listen://[::]:10943/ 7 Listener started
2016-12-29 13:06:26.2836 7 INFO The Octopus server is starting: Starting task scheduler…
2016-12-29 13:06:26.7836 7 INFO The Octopus server is starting: Starting task queue…
2016-12-29 13:06:26.8305 7 INFO Web server is ready to process requests
2016-12-29 13:06:26.8930 7 INFO The Windows Service has started
2016-12-29 13:06:31.8932 9 INFO The last SyncCommunityActionTemplates task finished only recently; waiting a little while before running again.
2016-12-29 13:06:57.0661 9 INFO The last health check for the machine policy Default Machine Policy finished only recently; waiting a little while before running again.
2016-12-29 13:07:27.2861 15 INFO Running System Integrity Check
2016-12-29 13:07:27.5986 15 INFO Completed System Integrity Check. Overall Result: Passed
2016-12-29 15:39:27.9828 9 INFO Reader took 401ms (400ms until the first record): SELECT * FROM dbo.[MachinePolicy] ORDER BY [Id]
2016-12-29 19:54:27.5295 9 INFO Reader took 303ms (303ms until the first record): SELECT * FROM dbo.[OctopusServerNode] WITH (UPDLOCK) ORDER BY [Id]
############################
This is the latest log after a refresh start up. When you see the port 81 come through, I had just clicked on the port 80 entry before that and gotten the error 503.
2016-12-30 00:09:27.5090 9 INFO Reader took 312ms (312ms until the first record): SELECT * FROM dbo.[MachinePolicy] ORDER BY [Id]
2016-12-30 00:27:06.9113 9 INFO Update took 379ms: UPDATE dbo.[OctopusServerNode] SET [Name] = @Name, [LastSeen] = @LastSeen, [Rank] = @Rank, [MaxConcurrentTasks] = @MaxConcurrentTasks, [IsInMaintenanceMode] = @IsInMaintenanceMode, [Json] = @Json WHERE Id = @Id
2016-12-30 02:03:05.0376 9 INFO Update took 611ms: UPDATE dbo.[OctopusServerNode] SET [Name] = @Name, [LastSeen] = @LastSeen, [Rank] = @Rank, [MaxConcurrentTasks] = @MaxConcurrentTasks, [IsInMaintenanceMode] = @IsInMaintenanceMode, [Json] = @Json WHERE Id = @Id
2016-12-30 10:02:35.8621 75 INFO Request took 1119ms: GET http://cd.deploy.beta.cd.it.app:81/api
So in working through a few more tests, if I bind localhost:80 and the cd.deploy.beta.cd.it.app to port 80 it will work, but I can only bind the first instance (and we have 7+ instances we need to host here). On the second instance if I don’t bind to localhost it brings me to the Web Portal of the first instance. If I bind to localhost:80 it fails to start because something is already listening there.
We tried setting up a virtual directory called /oo for the second instance using localhost:80/oo, this loaded, but when we created a new binding for oo-deploy-beta.ourdomain.com/ it failed, and when we added the /oo to the end, it also failed but in a strange way, it tried to open/download a file that couldn’t be saved or opened in Internet Explorer.
If we configure every instance with port 81, this works just fine, but we are unable to bind to port 80 without using localhost:80 on any instance.
I think we found the issue. Does Octopus do anything with http.sys ACLs when running as a service account or non-system account? Apparently members of the local administrators group bypass the ACLs, but anybody not in that group (ie service accounts) have to adhere to them, and Octopus was silently failing to receive any traffic due to the ACLs in place. It might be valuable to do a check of the ACLs when updating bindings.
We found some bad ACLs on http.sys that were preventing the Service Account we are using from listening on port 80 but allowed it to work on other ports where the ACLs weren’t present.
This tool helped tremendously, http://httpsysmanager.codeplex.com/ and I only came across it because of a post by the author. https://www.codeproject.com/Articles/437733/Demystify-http-sys-with-HttpSysManager
Download link: