Server cannot find free port for a TCP socket (1159)

[algernonz]

Halllo everyone,

This problem is happening on a Progress OpenEdge Release 9.1E on LINUX.
I sort of plunged into the middle of a migration project, and stubled upon this error of which I can't seem to find any Google history.
I can't make out how to tacle this above error.

The .pfs file looks like this

-S krzmtwp
-minport 2080
-maxport 2099

cat /etc/services says: krzmtwp 20022/tcp

# netstat -an --inet | grep 20022
tcp 0 0 0.0.0.0:20022 0.0.0.0:* LISTEN

# netstat -an --inet | grep 2080
# (nothing)

Startup logging + connection attempt show this:

Thu May 31 12:03:45 2012
12:03:45 BROKER 0: Multi-user session begin. (333)
12:03:45 BROKER 0: Begin Physical Redo Phase at 0 . (5326)
12:03:45 BROKER 0: Physical Redo Phase Completed at blk 0 off 515 upd 0. (7161)
12:03:45 BROKER 0: Started for krzmtwp using TCP, pid 9050. (5644)
12:03:45 BROKER 1: Started for krzmtwpsql using TCP, pid 9058. (5644)
12:03:45 BROKER 1: This is an additional broker for this protocol. (5645)
12:03:45 BROKER 1: This broker supports SQL server groups only. (8864)
12:03:45 WDOG 9: Started. (2518)
12:03:46 BROKER 0: Progress OpenEdge Release 9.1E on LINUX. (4234)
12:03:46 BROKER 0: Server started by progress on /dev/pts/0. (4281)
12:03:46 BROKER 0: Started using pid: 9050. (6574)
12:03:46 BROKER 0: Physical Database Name (-db): /usr/local/kra/tisp/db/mtwp. (4235)
12:03:46 BROKER 0: Database Type (-dt): PROGRESS. (4236)
12:03:46 BROKER 0: Force Access (-F): Not Enabled. (4237)
12:03:46 BROKER 0: Direct I/O (-directio): Not Enabled. (4238)
12:03:46 BROKER 0: Number of Database Buffers (-B): 32000. (4239)
12:03:46 BROKER 0: Maximum private buffers per user (-Bpmax): 64. (9422)
12:03:46 BROKER 0: Excess Shared Memory Size (-Mxs): 16472. (4240)
12:03:46 BROKER 0: The shared memory segment is not locked in memory. (10014)
12:03:46 BROKER 0: Current Size of Lock Table (-L): 150016. (4241)
12:03:46 BROKER 0: Hash Table Entries (-hash): 9337. (4242)
12:03:46 BROKER 0: Current Spin Lock Tries (-spin): 10000. (4243)
12:03:46 BROKER 0: Number of Semaphore Sets (-semsets): 4. (6526)
12:03:46 BROKER 0: Crash Recovery (-i): Enabled. (4244)
12:03:46 BROKER 0: Database Blocksize (-blocksize): 8192. (6573)
12:03:46 BROKER 0: Delay of Before-Image Flush (-Mf): 3. (4245)
12:03:46 BROKER 0: Before-Image File I/O (-r -R): Reliable. (4247)
12:03:46 BROKER 0: Before-Image Truncate Interval (-G): 0. (4249)
12:03:46 BROKER 0: Before-Image Cluster Size: 524288. (4250)
12:03:46 BROKER 0: Before-Image Block Size: 8192. (4251)
12:03:46 BROKER 0: Number of Before-Image Buffers (-bibufs): 500. (4252)
12:03:46 BROKER 0: BI File Threshold size (-bithold): 0.0 Bytes. (9238)
12:03:46 BROKER 0: BI File Threshold Stall (-bistall): Disabled. (6552)
12:03:46 BROKER 0: After-Image Stall (-aistall): Not Enabled. (4254)
12:03:46 BROKER 0: Number of After-Image Buffers (-aibufs): 5. (4256)
12:03:46 BROKER 0: Storage object cache size (-omsize): 1024 (8527)
12:03:46 BROKER 0: Maximum Number of Clients Per Server (-Ma): 50. (4257)
12:03:46 BROKER 0: Maximum Number of Servers (-Mn): 9. (4258)
12:03:46 BROKER 0: Minimum Clients Per Server (-Mi): 50. (4259)
12:03:46 BROKER 0: Maximum Number of Users (-n): 301. (4260)
12:03:46 BROKER 0: Host Name (-H): proz0099.tzzzz.lan. (4261)
12:03:46 BROKER 0: Service Name (-S): krzmtwp. (4262)
12:03:46 BROKER 0: Network Type (-N): TCP. (4263)
12:03:46 BROKER 0: Character Set (-cpinternal): ISO8859-1. (4264)
12:03:46 BROKER 0: Parameter File: /usr/local/kra/tisp/db/mtwp.pfs. (4282)
12:03:46 BROKER 0: Maximum Servers Per Broker (-Mpb): 6. (5647)
12:03:46 BROKER 0: Minimum Port for Auto Servers (-minport): 2080. (5648)
12:03:46 BROKER 0: Maximum Port for Auto Servers (-maxport): 2099. (5649)
12:03:46 BROKER 0: This broker supports 4GL server groups only. (8863)
12:03:46 BROKER 0: Created shared memory with segment_id: 3276820 (9336)
12:03:46 BROKER 0: Created shared memory with segment_id: 3309589 (9336)
12:03:46 BROKER 0: Created shared memory with segment_id: 3342358 (9336)
12:23:31 SRV 2: Server cannot find a free port for a TCP socket. (1159)
12:23:31 BROKER 0: 4GL server process terminated. (8837)
12:24:19 SRV 2: Server cannot find a free port for a TCP socket. (1159)
12:24:19 BROKER 0: 4GL server process terminated. (8837)

Any help will be much appreciated!

Algey

 

[Cringer]

Is anything else using any of the ports between
-minport 2080
-maxport 2099
?

 

[algernonz]

Is anything else using any of the ports between
-minport 2080
-maxport 2099
?

Hi, thanks for your answer.
According to netstat there are no ports used in between these numbers.

However, I noted one difference between the old, and the newly migrated database:
The ownership of the migrated database is progressrogress and the olf database was run as root.
But I don't think that is problematic, since connections to the tisp database are OK.

-rw-rw-r-- 1 progress progress 1073741824 May 31 12:03 mtwp.b1
-rw-rw-r-- 1 progress progress 32768 May 31 12:03 mtwp.b2
-rw-rw-r-- 1 progress progress 706347008 May 31 12:03 mtwp.d1
-rw-rw-r-- 1 progress progress 262144 May 31 12:03 mtwp.db
-rw-rw-r--. 1 progress progress 33267 May 31 12:24 mtwp.lg
-r--r----- 1 progress progress 1840 May 31 13:00 mtwp.lic
-r--r----- 1 root progress 38 May 31 12:03 mtwp.lk
-rw-r--r--. 1 root root 1416 Mar 2 14:50 mtwp.pfs
-rw-r--r--. 1 root root 968 Mar 2 14:50 mtwp.pfs-sql
-rw-r--r--. 1 root progress 132 Mar 1 15:57 mtwp.st
-rw-rw-r-- 1 progress progress 1073741824 May 29 14:44 tisp.b1
-rw-rw-r-- 1 progress progress 1073741824 May 29 14:43 tisp.b2
-rw-rw-r-- 1 progress progress 1073741824 May 29 14:43 tisp.b3
-rw-rw-r-- 1 progress progress 32768 May 29 14:43 tisp.b4
-rw-rw-r-- 1 progress progress 2147352576 May 31 00:03 tisp.d1
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d10
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d11
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d12
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d13
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d14
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d15
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:44 tisp.d16
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d17
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d18
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d19
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d2
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d20
-rw-rw-r-- 1 progress progress 32768 May 29 14:43 tisp.d21
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d3
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d4
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d5
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d6
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d7
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d8
-rw-rw-r-- 1 progress progress 2147352576 May 29 14:43 tisp.d9
-rw-rw-r-- 1 progress progress 262144 May 29 14:43 tisp.db
-rw-rw-r--. 1 progress progress 34946 May 31 12:24 tisp.lg
-r--r----- 1 progress progress 1880 May 31 13:00 tisp.lic
-r--r----- 1 root progress 38 May 29 14:44 tisp.lk
-rw-r--r--. 1 root progress 1415 Mar 2 14:50 tisp.pfs
-rw-r--r--. 1 root progress 957 Mar 2 14:50 tisp.pfs-sql
-rw-r--r--. 1 root progress 1470 Mar 1 15:57 tisp.st

 

[Rob Fitzpatrick]

You looked in your services file and in netstat for the broker port, but you also have to look for all of the ports in your minport/maxport range. If any of them are defined in the services file, even if they are not currently in use, then the broker will not spawn a 4GL server to listen on them. This is a known issue on Linux.

Check your services file (and netstat) for an available range of 20 ports, and use that for your minport/maxport. I also place a comment in the services file listing the range I have taken, so no one else will later think it's free.

 

[algernonz]

You looked in your services file and in netstat for the broker port, but you also have to look for all of the ports in your minport/maxport range. If any of them are defined in the services file, even if they are not currently in use, then the broker will not spawn a 4GL server to listen on them. This is a known issue on Linux.

Check your services file (and netstat) for an available range of 20 ports, and use that for your minport/maxport. I also place a comment in the services file listing the range I have taken, so no one else will later think it's free.

I defined another portrange in minport/maxport and the problem is solved.
I didn't know this was a known issue in linux.
Thanks!

 

[Rob Fitzpatrick]

http://progresscustomersupport-survey.force.com/ProgressKB/articles/Article/P128080

Apparently it's only a bug in 10.1 and 10.2, so maybe your issue is different. But it's still good practice to steer clear of defined ports.

 

[algernonz]

I also followed your advice to place a comment in the services file listing the range, so no one else will later think it's free.
This always works well when a server is administered by more then one person (and for later generations).
Thanks again.

 

[TomBascom]

I see your original problem is resolved but since you were so nice as to post your startup info I thought I'd add a few comments

Halllo everyone,

This problem is happening on a Progress OpenEdge Release 9.1E on LINUX.

It is obligatory to mention that this release is ancient, obsolete and unsupported... did they even have TCP/IP that long ago?

...
Startup logging + connection attempt show this:

Thu May 31 12:03:45 2012
12:03:45 BROKER 0: Multi-user session begin. (333)
12:03:45 BROKER 0: Begin Physical Redo Phase at 0 . (5326)
12:03:45 BROKER 0: Physical Redo Phase Completed at blk 0 off 515 upd 0. (7161)
12:03:45 BROKER 0: Started for krzmtwp using TCP, pid 9050. (5644)
12:03:45 BROKER 1: Started for krzmtwpsql using TCP, pid 9058. (5644)
12:03:45 BROKER 1: This is an additional broker for this protocol. (5645)
12:03:45 BROKER 1: This broker supports SQL server groups only. (8864)

Excellent! It is a very good thing to have a distinct broker for SQL connections. Congratulations.

12:03:45 WDOG 9: Started. (2518)
12:03:46 BROKER 0: Progress OpenEdge Release 9.1E on LINUX. (4234)
12:03:46 BROKER 0: Server started by progress on /dev/pts/0. (4281)
12:03:46 BROKER 0: Started using pid: 9050. (6574)
12:03:46 BROKER 0: Physical Database Name (-db): /usr/local/kra/tisp/db/mtwp. (4235)
12:03:46 BROKER 0: Database Type (-dt): PROGRESS. (4236)
12:03:46 BROKER 0: Force Access (-F): Not Enabled. (4237)
12:03:46 BROKER 0: Direct I/O (-directio): Not Enabled. (4238)
12:03:46 BROKER 0: Number of Database Buffers (-B): 32000. (4239)

32,000 isn't really very much. (just 256MB with 8k db blocks...) How much RAM do you actually have?

12:03:46 BROKER 0: Maximum private buffers per user (-Bpmax): 64. (9422)
12:03:46 BROKER 0: Excess Shared Memory Size (-Mxs): 16472. (4240)
12:03:46 BROKER 0: The shared memory segment is not locked in memory. (10014)
12:03:46 BROKER 0: Current Size of Lock Table (-L): 150016. (4241)
12:03:46 BROKER 0: Hash Table Entries (-hash): 9337. (4242)
12:03:46 BROKER 0: Current Spin Lock Tries (-spin): 10000. (4243)
12:03:46 BROKER 0: Number of Semaphore Sets (-semsets): 4. (6526)
12:03:46 BROKER 0: Crash Recovery (-i): Enabled. (4244)
12:03:46 BROKER 0: Database Blocksize (-blocksize): 8192. (6573)
12:03:46 BROKER 0: Delay of Before-Image Flush (-Mf): 3. (4245)
12:03:46 BROKER 0: Before-Image File I/O (-r -R): Reliable. (4247)
12:03:46 BROKER 0: Before-Image Truncate Interval (-G): 0. (4249)
12:03:46 BROKER 0: Before-Image Cluster Size: 524288. (4250)

That looks suspiciously like the default bi cluster size. You would do well to increase it. "proutil dbName -C truncate bi -bi 16384" would be a good start.

12:03:46 BROKER 0: Before-Image Block Size: 8192. (4251)
12:03:46 BROKER 0: Number of Before-Image Buffers (-bibufs): 500. (4252)

And that is a very unusually high value for -bibufs. Which leads me to think that you have transaction throughput issues that would be better solved by increasing the bi cluster size.

12:03:46 BROKER 0: BI File Threshold size (-bithold): 0.0 Bytes. (9238)
12:03:46 BROKER 0: BI File Threshold Stall (-bistall): Disabled. (6552)
12:03:46 BROKER 0: After-Image Stall (-aistall): Not Enabled. (4254)
12:03:46 BROKER 0: Number of After-Image Buffers (-aibufs): 5. (4256)

I get the feeliing that after-imaging is NOT enabled. Does you data have any value to you or your company? If it does then you should stop everything else that you are doing and properly enable after-imaging RIGHT NOW.

12:03:46 BROKER 0: Storage object cache size (-omsize): 1024 (8527)
12:03:46 BROKER 0: Maximum Number of Clients Per Server (-Ma): 50. (4257)
12:03:46 BROKER 0: Maximum Number of Servers (-Mn): 9. (4258)
12:03:46 BROKER 0: Minimum Clients Per Server (-Mi): 50. (4259)

This is wierd. A much more normal set of values would be -Mn 100 -Ma 5 -Mi 1. The way this is set up the first 50 connections will pool on just a single server. The 51st connection will (finally) start on a 2nd server. That isn't going to perform very well.

12:03:46 BROKER 0: Maximum Number of Users (-n): 301. (4260)
12:03:46 BROKER 0: Host Name (-H): proz0099.tzzzz.lan. (4261)
12:03:46 BROKER 0: Service Name (-S): krzmtwp. (4262)
12:03:46 BROKER 0: Network Type (-N): TCP. (4263)
12:03:46 BROKER 0: Character Set (-cpinternal): ISO8859-1. (4264)
12:03:46 BROKER 0: Parameter File: /usr/local/kra/tisp/db/mtwp.pfs. (4282)
12:03:46 BROKER 0: Maximum Servers Per Broker (-Mpb): 6. (5647)

That should change to 100 if you take my -Mn advice above...

12:03:46 BROKER 0: Minimum Port for Auto Servers (-minport): 2080. (5648)
12:03:46 BROKER 0: Maximum Port for Auto Servers (-maxport): 2099. (5649)
12:03:46 BROKER 0: This broker supports 4GL server groups only. (8863)
12:03:46 BROKER 0: Created shared memory with segment_id: 3276820 (9336)
12:03:46 BROKER 0: Created shared memory with segment_id: 3309589 (9336)
12:03:46 BROKER 0: Created shared memory with segment_id: 3342358 (9336)
12:23:31 SRV 2: Server cannot find a free port for a TCP socket. (1159)
12:23:31 BROKER 0: 4GL server process terminated. (8837)
12:24:19 SRV 2: Server cannot find a free port for a TCP socket. (1159)
12:24:19 BROKER 0: 4GL server process terminated. (8837)

Any help will be much appreciated!

Algey

And if everything is in the schema area you ought to fix that too.