[0.16.51] Server with custom port sets different port than specified

[DDDGamer]

Trying to set a custom port for factorio server (in order to run 2 separate servers, and also have default port reserved for my local steam client game)
But instead of my specified port, the game sets one up to be 1024, and 1025 for second server, i imagine 1026, etc.. if one has more

Also this does not happen always, sometimes it would get the 1024 address sometimes not

Log:

Code: Select all

0.000 2018-10-04 15:52:30; Factorio 0.16.51 (build 36654, linux64, headless)
0.000 Operating system: Linux
0.000 Program arguments: "/opt/factorio/bin/x64/factorio" "--port" "34196" "--start-server-load-latest" "--server-settings" "/factorio/config/server-settings.json" "--server-whitelist" "/factorio/config/server-whitelist.json" "--server-banlist" "/factorio/config/server-banlist.json" "--rcon-port" "27015" "--rcon-password" <private> "--server-id" "/factorio/config/server-id.json"
0.000 Read data path: /opt/factorio/data
0.000 Write data path: /opt/factorio [15367/20480MB]
0.000 Binaries path: /opt/factorio/bin
0.005 System info: [CPU: Intel(R) Xeon(R) CPU E3-1231 v3 @ 3.40GHz, 8 cores, RAM: 16072 MB]

0.005 Environment: DISPLAY=<unset>, WAYLAND_DISPLAY=<unset>
0.005 Running in headless mode
0.007 Loading mod core 0.0.0 (data.lua)
0.015 Loading mod base 0.16.51 (data.lua)
0.111 Loading mod base 0.16.51 (data-updates.lua)
0.148 Checksum for core: 840319042

0.148 Checksum of base: 3323233190

0.221 Info PlayerData.cpp:65: Local player-data.json available, timestamp 1538668294
0.221 Info PlayerData.cpp:72: Cloud player-data.json unavailable
0.222 Custom inputs active: 0
0.111 Loading mod base 0.16.51 (data-updates.lua)
0.148 Checksum for core: 840319042

0.148 Checksum of base: 3323233190

0.221 Info PlayerData.cpp:65: Local player-data.json available, timestamp 1538668294
0.221 Info PlayerData.cpp:72: Cloud player-data.json unavailable
0.222 Custom inputs active: 0
1.076 0 packages available to download (experimental updates disabled).
1.076 Factorio initialised
1.080 Info ServerSynchronizer.cpp:29: nextHeartbeatSequenceNumber(0) initialized Synchronizer nextTickClosureTick(0).
1.080 Info ServerMultiplayerManager.cpp:699: mapTick(4294967295) changing state from(Ready) to(PreparedToHostGame)
1.080 Info ServerMultiplayerManager.cpp:699: mapTick(4294967295) changing state from(PreparedToHostGame) to(CreatingGame)
1.081 Loading map /factorio/saves/_autosave1.zip: 11900141 bytes.
1.092 Loading Level.dat: 32536280 bytes.
1.096 Info Scenario.cpp:136: Map version 0.16.51-0

3.140 Loading script.dat: 880 bytes.
3.144 Checksum for script /opt/factorio/temp/currently-playing/control.lua: 246304608

1.875 Info UDPSocket.cpp:27: Opening socket at (IP ADDR:({0.0.0.0:34196}))
1.876 Hosting game at IP ADDR:({0.0.0.0:34196})
1.876 Info HttpSharedState.cpp:54: Downloading https://auth.factorio.com/generate-server-padlock-2
2.076 Info HttpSharedState.cpp:145: Status code: 200
2.076 Info AuthServerConnector.cpp:109: Obtained serverPadlock for serverHash (FPfEcMDVjcEIjgV302z5fZmfipZ4ZHlR) from the auth server.
2.076 Info ServerMultiplayerManager.cpp:699: mapTick(9462767) changing state from(CreatingGame) to(InGame)
2.076 Info ServerRouter.cpp:596: Asking pingpong servers (pingpong1.factorio.com:34197, pingpong2.factorio.com:34197) for own address
2.125 Info UDPSocket.cpp:39: Opening socket for broadcast
2.145 Error InterruptibleStdioStream.cpp:54: Reading stdin failed

2.145 Info RemoteCommandProcessor.cpp:128: Starting RCON interface at port 27015
2.264 Info ServerRouter.cpp:491: Own address is IP ADDR:({x.x.x.x:1024})
2.507 Info MatchingServer.cpp:86: Matching server game `3324159` has been created.
2.517 Info ServerMultiplayerManager.cpp:628: Matching server connection resumed

As i understand
1.875 Info UDPSocket.cpp:27: Opening socket at (IP ADDR:({0.0.0.0:34196})) <- port 34196
1.876 Hosting game at IP ADDR:({0.0.0.0:34196}) <- port 34196
2.076 Info ServerRouter.cpp:596: Asking pingpong servers (pingpong1.factorio.com:34197, pingpong2.factorio.com:34197) for own address
2.264 Info ServerRouter.cpp:491: Own address is IP ADDR:({x.x.x.x:1024}) <- port 1024, expected 34196 (replaced my ip with x.x.x.x)

Here is a successfull one:

Code: Select all

0.000 2018-10-04 16:07:19; Factorio 0.16.51 (build 36654, linux64, headless)
0.000 Operating system: Linux
0.000 Program arguments: "/opt/factorio/bin/x64/factorio" "--port" "34198" "--start-server-load-latest" "--server-settings" "/factorio/config/server-settings.json" "--server-whitelist" "/factorio/config/server-whitelist.json" "--server-banlist" "/factorio/config/server-banlist.json" "--rcon-port" "27015" "--rcon-password" <private> "--server-id" "/factorio/config/server-id.json"
0.000 Read data path: /opt/factorio/data
0.000 Write data path: /opt/factorio [15367/20480MB]
0.000 Binaries path: /opt/factorio/bin
0.005 System info: [CPU: Intel(R) Xeon(R) CPU E3-1231 v3 @ 3.40GHz, 8 cores, RAM: 16072 MB]

0.005 Environment: DISPLAY=<unset>, WAYLAND_DISPLAY=<unset>
0.005 Running in headless mode
0.007 Loading mod core 0.0.0 (data.lua)
0.016 Loading mod base 0.16.51 (data.lua)
0.121 Loading mod base 0.16.51 (data-updates.lua)
0.155 Checksum for core: 840319042

0.155 Checksum of base: 3323233190

0.231 Info PlayerData.cpp:65: Local player-data.json available, timestamp 1538668972
0.231 Info PlayerData.cpp:72: Cloud player-data.json unavailable
0.232 Custom inputs active: 0
1.372 0 packages available to download (experimental updates disabled).
1.372 Factorio initialised
1.379 Info ServerSynchronizer.cpp:29: nextHeartbeatSequenceNumber(0) initialized Synchronizer nextTickClosureTick(0).
1.379 Info ServerMultiplayerManager.cpp:699: mapTick(4294967295) changing state from(Ready) to(PreparedToHostGame)
1.379 Info ServerMultiplayerManager.cpp:699: mapTick(4294967295) changing state from(PreparedToHostGame) to(CreatingGame)
1.379 Loading map /factorio/saves/_autosave1.zip: 17795744 bytes.
1.387 Loading Level.dat: 49489730 bytes.
1.393 Info Scenario.cpp:136: Map version 0.16.51-0

2.480 Loading script.dat: 1508 bytes.
2.484 Checksum for script /opt/factorio/temp/currently-playing/control.lua: 997060638

2.498 Info UDPSocket.cpp:27: Opening socket at (IP ADDR:({0.0.0.0:34198}))
2.498 Hosting game at IP ADDR:({0.0.0.0:34198})
2.498 Info HttpSharedState.cpp:54: Downloading https://auth.factorio.com/generate-server-padlock-2
2.670 Info HttpSharedState.cpp:145: Status code: 200
2.670 Info AuthServerConnector.cpp:109: Obtained serverPadlock for serverHash (Xx71rRr777Q0mAA4vgE44822QMaH76UP) from the auth server.
2.670 Info ServerMultiplayerManager.cpp:699: mapTick(21193782) changing state from(CreatingGame) to(InGame)
2.670 Info ServerRouter.cpp:596: Asking pingpong servers (pingpong1.factorio.com:34197, pingpong2.factorio.com:34197) for own address
2.718 Info UDPSocket.cpp:39: Opening socket for broadcast
2.738 Error InterruptibleStdioStream.cpp:54: Reading stdin failed

2.739 Info RemoteCommandProcessor.cpp:128: Starting RCON interface at port 27015
2.859 Info ServerRouter.cpp:491: Own address is IP ADDR:({x.x.x.x:34198})
3.095 Info MatchingServer.cpp:86: Matching server game `3324241` has been created.
3.112 Info ServerMultiplayerManager.cpp:628: Matching server connection resumed

2.498 Info UDPSocket.cpp:27: Opening socket at (IP ADDR:({0.0.0.0:34198})) <- port 34198
2.498 Hosting game at IP ADDR:({0.0.0.0:34198}) <- port 34198
2.670 Info ServerRouter.cpp:596: Asking pingpong servers (pingpong1.factorio.com:34197, pingpong2.factorio.com:34197) for own address
2.859 Info ServerRouter.cpp:491: Own address is IP ADDR:({x.x.x.x:34198}) <- as expected port 34198

[AreYouScared]

I too have had this issue with running Linux headless, try another port? That's what i did and it fixed itself for me

[Zavian]

Any chance you are behind a router doing NAT? Because if you are then it sounds like you should setup some static port forwarding rules.

[DDDGamer]

Port forwarding has been already set up

[Rseding91]

Have you tested that it's actually using that port? Because if I understand it correctly: all that's saying is "when you asked the server 'what is my IP'" the server said it was 'X...' and the port during that request doesn't matter.

[DDDGamer]

Not sure what you mean by testing that is actually using the port.
If its

Code: Select all

2.264 Info ServerRouter.cpp:491: Own address is IP ADDR:({x.x.x.x:1024})

then the game doesnt show up in the lobby, and i cant connect with the direct server option (ill have to retest and see if i can connect on port 1024 instead when/if it happens again)
and if its

Code: Select all

2.859 Info ServerRouter.cpp:491: Own address is IP ADDR:({x.x.x.x:34198}) <- as expected port 34198

then the game shows up and i can connect

So are you suggesting that the port is system specific and have nothing to do with factorio server's matching connections? (I do not know how that works)

[Syhn]

I too have run into this issue. I've found that running a Factorio server inside docker with an image from https://github.com/factoriotools/factorio-docker works normally, however, when I build the image myself from the Dockerfile, it advertises port 1024 to the server list for a while until it finally corrects itself. I will look into it more when I have some spare time. Definitely a puzzling issue.

As a side note: it would be nice to be able to explicitly specify the port to advertise to help with the cases of docker remapping ports. Currently, the external port has to map to the internal port or else the internal port will be advertised, which obviously doens't work when attempting to connect to the server outside of docker.

[psihius]

We also have run into it with our Clusterio servers. We also run docker, but we have docker-proxy disabled, iptables have rules properly setup and ports are exposed to the outer wild (confirmed by netstat and dumping and reviewing iptables rules).

One strange thing we found out, that despite the port being exposed - people were not able to telenet into it. I don't know if it is a docker problem or a combo of docker+factorio in some way. We had a game port at 5000 and RCON port at 5001 - 5000 was not connectable and 5001 was just fine. I flipped the ports around - 5000 for RCON and 5001 for the game and it all just worked after a container restart. And the thing is - that happens sometimes randomly.

I never had issues with docker port forwarding not working, and that would have been a major issue because you know, there are whole clusters of docker based clouds living in the wild, so my feeling is this is might be a combo of the game networking + docker leading to some unpredictable issues.

Maybe enabling extended logging while running the game might help with info gathering on this one?

0.17.53 and 0.17.54 for us.

[AreYouScared]

Here's a interesting startup

Server knows its hosting on 10001
But pingpong expected 1027?
But pingpong got 1028?

As the server is already sending information to the master when it creates the game for the multiplayer list why can't it just tell it the port it was given to use? And only use pingpong to determine pubic ip?

[posila]

As the server is already sending information to the master when it creates the game for the multiplayer list why can't it just tell it the port it was given to use? And only use pingpong to determine pubic ip?

For the same reason we need pingpong server to determine public IP, we need it to determine what port is the game seen as sending packets from outside world.
Some network device between your computer and rest of the internet changes it. And in your case, it's changed differently for connections to different computers.

(The logic behind the log message is basically just Factorio receving from pingpong server 1 its IP and port is A, and from pingpong server 2 its IP and port is B, than realizing A != B and spitting out a message "I got B but was expecting A")

[Oxyd]

One of the Gridlock members sent me a packet trace and it showed the pingpong packets being resent with a different source port.

To me this sounds very much like misconfigured networking on the server side.

[boskid]

(The logic behind the log message is basically just Factorio receving from pingpong server 1 its IP and port is A, and from pingpong server 2 its IP and port is B, than realizing A != B and spitting out a message "I got B but was expecting A")

https://en.wikipedia.org/wiki/Network_a ... ranslation

Maybe better message would be "You(server) are behind NAT that appears to be Restricted-cone (symmetric NAT), Cannot host game as players would not be able to connect. Please configure port forwarding instead [cannot punch udp port in router]"

[psihius]

We think we did identify why this might be happening - it is possible that Docker needs some stern configuration directives that do not allow it to have a mind of it's own.
So far we do not know if that is even possible, but it also does not make it easy because it is random. The failure rate is between 1/10 - 1/15, and some instances never encounter this issue (we have over 40 instances, so we get the occasional error every few days).

Will post an update when we manage or fail to wrestle this on our side.
I mean, this is not really something an average player can figure out or know what to do about. And since we are using the Pterodactyl panel to manage docker instances - this might require fixes on their side and they might just refuse. And a lot of these errors actually come from their usage.

A better error message would be nice, yes. Also maybe check that game is connectable from the ping-pong server and fail loudly if the port is actually not reachable? It sucks to have users report after 2-3 hours that they can't enter a server and 80% just thought "oh well, I'm gonna go elsewhere".

[Oxyd]

Also maybe check that game is connectable from the ping-pong server and fail loudly if the port is actually not reachable? It sucks to have users report after 2-3 hours that they can't enter a server and 80% just thought "oh well, I'm gonna go elsewhere".

But it is reachable. The pingpong server sends its reply to the address and port you are seeing. If you are seeing the reply, it means the reply must have reached you on that address and port.

If you figure out what's wrong with Docker, then definitely let us know all the details.

[boskid]

But it is reachable. The pingpong server sends its reply to the address and port you are seeing. If you are seeing the reply, it means the reply must have reached you on that address and port.

This depends on NAT implementation (look at https://en.wikipedia.org/wiki/Network_a ... ranslation). In Symetric NAT, router records both internal ip:port and external ip:port, and so external ip:port as seen by pingpong1 will be usable only by pingpong1 only from same port it was contacted to. This case is "hard" as NAT traversal may not be possible. This case can be however detected using following protocol:

client -> pingpong1: "hey, what is my ip:port from your side (after NAT)?"
pingpong1 -> client: "your public ip:port (as seen from pingpong1) is 203.0.113.1 port 1234"
pingpong1 -> pingpong2: "could you please send for me UDP frame to 203.0.113.1 port 1234?"
pingpong2 -> client: "hey, i am message sent from different ip and different port, can you hear me?"

If client receives message from pingpong2 then NAT is not Symetric NAT and so it should be able to accept client connections (well, it already accepted udp packet from different ip/port)

[psihius]

Also maybe check that game is connectable from the ping-pong server and fail loudly if the port is actually not reachable? It sucks to have users report after 2-3 hours that they can't enter a server and 80% just thought "oh well, I'm gonna go elsewhere".

But it is reachable. The ping-pong server sends its reply to the address and port you are seeing. If you are seeing the reply, it means the reply must have reached you on that address and port.

If you figure out what's wrong with Docker, then definitely let us know all the details.

True story:

Game starts on 0.0.0.0:10000 (inside docker).
Docker sets port forwarding to the outside world on port 10000
iptables, netstat and docker ps all show that port is forwarded and port is open on 94.237.42.157:10000 and routed to docker internals to docker_ip:10000
The game sends the request to ping-pong servers
Ping pong servers reply: 94.237.42.157:1025
The game says - okay! and lists on the game browser as 94.237.42.157:1025
I go into the game browser and get an error "Cannot connect to the game". The port is listed as 1025
I go into manual connect, enter 94.237.42.157:10000 and successfully connect to the game.

WTF ensues

[slippycheeze]

But it is reachable. The pingpong server sends its reply to the address and port you are seeing. If you are seeing the reply, it means the reply must have reached you on that address and port.

This depends on NAT implementation (look at https://en.wikipedia.org/wiki/Network_a ... ranslation). In Symetric NAT, router records both internal ip:port and external ip:port, and so external ip:port as seen by pingpong1 will be usable only by pingpong1 only from same port it was contacted to. This case is "hard" as NAT traversal may not be possible. This case can be however detected using following protocol:

I cannot possibly put this strongly enough: using ICE, possibly in connection with "UPnP" and NAT-PMP support, is the best, and most sensible, way to solve this problem. It is an incredibly annoyingly hard problem, because not only so many ways NAT can mess things up, but because 99 percent of those NAT setups have a "don't be stupid" flag somewhere - and if you don't set it, it'll be really stupid.

Sadly, the default configuration often has the "don't be stupid" flag set to false out of the box, for horrible historical reasons.

ICE is designed, standardized, and maintained to let SIP work through firewalls, and if you ever looked at it, SIP is what you would get if you thought "I want to make a protocol as hostile to NAT as possible." (Well, OK, I might be biased because I only dealt with the failure modes, and they hurt a lot.)


I have in past lives thought "I'll just build a NAT traversal / detection protocol" and done so. Every single time I regretted my life choices intensely, because it was a poorly specified, half complete implementation of STUN/TURN/ICE, and it hit every problem the IETF WG, and the companies behind the protocols, already found in designing and deploying these at scale.

edit to add: the described protocol isn't actually bad, and some of what earlier was described is similar to STUN/TURN/ICE decision trees, etc, but I *think* they are not full blown version of the same.

NAT vs UDP is the worst of the worst. There are many firewalls that impose scary limits like easily configured < 1 second timeouts for outbound UDP port continuity, or that simply drop UDP NAT mapping 33 of the 32 slots (16, because they use one each way) they maintain, leading to a touch of flapping...


So, yah, I would encourage solving this by using ICE, not through any other path. I hope to save you the same pain and suffering I went through, and the knowledge that this was all at your own hand.

(I still feel a little better when I remember ICE postdates several of my decisions to design my own protocol though.)

PS: today, if I had the choice, I'd try and figure out if I could carry my data over WebRTC, just because it will be the most reliable (as in, actually tested by NAT implementers) protocol just because browsers use it, and internet-based video chat services will use it.

[boskid]

This went too far. Lets go back to docker things.

Maybe issue is that using docker's "-p 10000:10000" sets up DNAT that can be used to accept incoming udp datagrams (first incoming frame goes by DNAT rule, responses fall into RELATED rule and are mapped properly), but since first packet (to pingpoing) is outgoing, it may miss DNAT (not incoming, not related) rule and create temporary mapping from internal_ip:port onto external_ip:1025, this gives wrong external port and everything collapses. (never used docker at full scale, i may be wrong here).

Better test of docker's port forwarding would be to map internal port !=10000 to port ==10000 to check if outgoing packets fall into docker's port forwarding rule. If not, it was working 9 out of 10 times by pure luck. If it is working, then issue may be different

[Rseding91]

I'm going to move this to 0/1 magic.