Map download never finishes [14.5] headless windows

[giich]

Hi.

I'm trying to set up a server. I've got my IP adress from prov and forwarded ports (TCP too, for good measure ) 34197. But when i try to join my game client download map and then it stops like on the screenshot.

Nothing happens. Any guess?

[Deadly-Bagel]

Update to the latest 14.x as multiplayer has been completely rewritten, so there isn't any point in debugging this old version.

[giich]

Same with 14.5 both client and server

[giich]

14.5 version drops client after awhile. 13.20 does not, but problem stays

Code: Select all

  
   0.002 2016-09-14 14:23:22; Factorio 0.14.5 (build 24594, win64, alpha)
   0.005 Operating system: Windows 10
   0.006 Program arguments: "factorio.exe" "--start-server" "server.zip" "--server-settings" "server-settings.json"
   0.010 Read data path: C:/Users/legio_000/Desktop/Factorio_0.14.5/data
   0.012 Write data path: C:/Users/legio_000/Desktop/Factorio_0.14.5
   0.015 Binaries path: C:/Users/legio_000/Desktop/Factorio_0.14.5/bin
   0.040 Running in headless mode
   0.046 Loading mod core 0.0.0 (data.lua)
   0.054 Loading mod base 0.14.5 (data.lua)
   0.207 Checksum for core: 1620335853
   0.367 Checksum for mod base: 574141439
   0.909 Info PlayerData.cpp:45: Local player-data.json available, timestamp 1473852138
   0.913 Info PlayerData.cpp:52: Cloud player-data.json unavailable
   0.925 Custom inputs active: 0
   0.930 Factorio initialised
   0.933 Info ServerSynchronizer.cpp:27: nextHeartbeatSequenceNumber(0) initialized Synchronizer nextTickClosureTick(0).
   0.937 Info ServerMultiplayerManager.cpp:625: mapTick(-1) changing state from(Ready) to(PreparedToHostGame)
   0.941 Info ServerMultiplayerManager.cpp:625: mapTick(-1) changing state from(PreparedToHostGame) to(CreatingGame)
   0.946 Loading map C:\Users\legio_000\Desktop\Factorio_0.14.5\bin\x64\server.zip
   1.046 Info Scenario.cpp:148: Map version 0.14.5-3
   4.037 Checksum for script C:/Users/legio_000/Desktop/Factorio_0.14.5/temp/currently-playing/control.lua: 900459546
   4.072 Info WindowsUDPSocket.cpp:61: Opening socket at port (34197)
   4.076 Hosting game at port 34197
   4.082 Info ServerMultiplayerManager.cpp:625: mapTick(3563991) changing state from(CreatingGame) to(InGame)
  17.581 ConnectionRequestReplyConfirm (type(ConnectionRequestReplyConfirm) ) from(46.39.244.34:55764)
  17.590 Info ServerRouter.cpp:418: Replying to connectionRequest for address(46.39.244.34:55764).
  17.599 Info ServerSynchronizer.cpp:504: nextHeartbeatSequenceNumber(0) adding peer(1)
  17.604 Info ServerMultiplayerManager.cpp:625: mapTick(3563991) changing state from(InGame) to(InGameSavingMap)
  17.629 Info ServerMultiplayerManager.cpp:701: mapTick(3563991) received stateChanged peerID(1) oldState(Ready) newState(ConnectedWaitingForMap)
  19.355 Info ServerMultiplayerManager.cpp:733: MapTick(3563991) Serving map(C) for peer(1) size(18546795) crc(1744126676)
  19.361 Info ServerMultiplayerManager.cpp:625: mapTick(3563991) changing state from(InGameSavingMap) to(InGame)
  19.435 Info ServerMultiplayerManager.cpp:701: mapTick(3563999) received stateChanged peerID(1) oldState(ConnectedWaitingForMap) newState(ConnectedDownloadingMap)
  93.619 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2001) peer(1) wants a heartbeat(1688) that we don't have.
  94.191 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2016) peer(1) wants a heartbeat(1688) that we don't have.
  94.755 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2031) peer(1) wants a heartbeat(1688) that we don't have.
  95.314 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2046) peer(1) wants a heartbeat(1688) that we don't have.
  95.889 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2061) peer(1) wants a heartbeat(1688) that we don't have.
  96.447 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2076) peer(1) wants a heartbeat(1688) that we don't have.
  97.016 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2091) peer(1) wants a heartbeat(1688) that we don't have.
  97.588 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2106) peer(1) wants a heartbeat(1688) that we don't have.
  98.150 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2121) peer(1) wants a heartbeat(1688) that we don't have.
  98.721 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2136) peer(1) wants a heartbeat(1688) that we don't have.
  99.285 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2151) peer(1) wants a heartbeat(1688) that we don't have.
  99.848 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2166) peer(1) wants a heartbeat(1688) that we don't have.
 100.411 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2181) peer(1) wants a heartbeat(1688) that we don't have.
 100.984 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2195) peer(1) wants a heartbeat(1688) that we don't have.
 101.551 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2210) peer(1) wants a heartbeat(1688) that we don't have.
 102.120 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2225) peer(1) wants a heartbeat(1688) that we don't have.
 102.686 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2240) peer(1) wants a heartbeat(1688) that we don't have.
 103.245 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2255) peer(1) wants a heartbeat(1688) that we don't have.
 103.813 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2270) peer(1) wants a heartbeat(1688) that we don't have.
 104.381 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2284) peer(1) wants a heartbeat(1688) that we don't have.
 104.961 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2300) peer(1) wants a heartbeat(1688) that we don't have.
 105.514 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2315) peer(1) wants a heartbeat(1688) that we don't have.
 106.081 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2330) peer(1) wants a heartbeat(1688) that we don't have.
 106.661 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2345) peer(1) wants a heartbeat(1688) that we don't have.
 107.224 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2360) peer(1) wants a heartbeat(1688) that we don't have.
 107.782 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2375) peer(1) wants a heartbeat(1688) that we don't have.
 108.349 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2390) peer(1) wants a heartbeat(1688) that we don't have.
 108.922 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2405) peer(1) wants a heartbeat(1688) that we don't have.
 109.494 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2420) peer(1) wants a heartbeat(1688) that we don't have.
 110.051 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2435) peer(1) wants a heartbeat(1688) that we don't have.
 110.624 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2449) peer(1) wants a heartbeat(1688) that we don't have.
 111.192 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2464) peer(1) wants a heartbeat(1688) that we don't have.
 111.757 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2478) peer(1) wants a heartbeat(1688) that we don't have.
 112.316 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2493) peer(1) wants a heartbeat(1688) that we don't have.
 112.892 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2508) peer(1) wants a heartbeat(1688) that we don't have.
 113.456 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2523) peer(1) wants a heartbeat(1688) that we don't have.
 114.012 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2538) peer(1) wants a heartbeat(1688) that we don't have.
 114.583 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2553) peer(1) wants a heartbeat(1688) that we don't have.
 115.156 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2568) peer(1) wants a heartbeat(1688) that we don't have.
 115.729 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2583) peer(1) wants a heartbeat(1688) that we don't have.
 116.280 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2598) peer(1) wants a heartbeat(1688) that we don't have.
 116.851 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2613) peer(1) wants a heartbeat(1688) that we don't have.
 117.425 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2628) peer(1) wants a heartbeat(1688) that we don't have.
 117.985 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2643) peer(1) wants a heartbeat(1688) that we don't have.
 118.559 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2658) peer(1) wants a heartbeat(1688) that we don't have.
 119.120 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2673) peer(1) wants a heartbeat(1688) that we don't have.
 119.679 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2688) peer(1) wants a heartbeat(1688) that we don't have.
 120.246 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2703) peer(1) wants a heartbeat(1688) that we don't have.
 120.829 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2718) peer(1) wants a heartbeat(1688) that we don't have.
 121.379 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2733) peer(1) wants a heartbeat(1688) that we don't have.
 121.955 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2748) peer(1) wants a heartbeat(1688) that we don't have.
 122.525 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2763) peer(1) wants a heartbeat(1688) that we don't have.
 123.092 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2778) peer(1) wants a heartbeat(1688) that we don't have.
 123.650 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2792) peer(1) wants a heartbeat(1688) that we don't have.
 124.222 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2807) peer(1) wants a heartbeat(1688) that we don't have.
 124.789 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2822) peer(1) wants a heartbeat(1688) that we don't have.
 125.344 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2837) peer(1) wants a heartbeat(1688) that we don't have.
 125.914 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2852) peer(1) wants a heartbeat(1688) that we don't have.
 126.498 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2867) peer(1) wants a heartbeat(1688) that we don't have.
 127.061 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2881) peer(1) wants a heartbeat(1688) that we don't have.
 127.613 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2896) peer(1) wants a heartbeat(1688) that we don't have.
 128.185 Warning ServerSynchronizer.cpp:112: nextHeartbeatSequenceNumber(2911) peer(1) wants a heartbeat(1688) that we don't have.
 140.659 Info ServerMultiplayerManager.cpp:775: Disconnect notification for peer (1)
 149.772 Info ServerSynchronizer.cpp:519: nextHeartbeatSequenceNumber(3234) removing peer(1).

[giich]

I've tried to rehost server with GUI, and here what i got from server side. From Client side it is all the same like the headless. It's stuck the same way, but screenshot is taken when it still not showing 0 bps, but it eventially comes there.

Also, i mentioned that he tries to upload 21 mb of map, when client downloading only 18. The size of the real save file is 18 mb.

[giich]

Here comes the fun part

I've managed to run server on empty save file O_O WTF

Based upon that fact, i could say it was not the hardware problem, but something caused desync in the factorio application itself... I mean specific savefile. Bug? Don't know. I will check if i'll get consistent results from different access points, and continue reporting.

Added:
Shortly after, i've left the server and tried to rejoin. Guess what? It stuck again Look's like it stops working after save is more than 2 mb or so.

[flonussi]

Hi,
were you able to find a solution for this issue?
Because i have the same issue with the latest version of factorio...
I cannot connect to the server, it always stops downloading at 100%...

Thanks

[dadymax]

Hello.

Same problem here.
Headless server and user is on latest 0.14.21. Other users didn't have any problem with initial connection to server (but from time to time have problems with desyncs - other story) but I can not normally connect to server: I need restart Factorio one-ten-twenty times before it can download map and login to server. Server restart can also solve my connection problem, but not always.

Server admin and I can not determine exacly source of problem but problem exist.

Connection to server is successfull, map started download at full 100 Mbit/s speed as should, download proceed to the end of progress bar and then speed is fall to 0 bit/s in about 2-3s and stay in this position forever. Factorio is in download map state (as stated in log:

40.808 Info ClientMultiplayerManager.cpp:669: Received mapReadyForDownload
40.808 Downloading file C:\Users\umka\AppData\Roaming\Factorio\temp\mp-download.zip (31713568 B, 63049 blocks)
40.812 Info ClientMultiplayerManager.cpp:539: MapTick(-1) changing state from(ConnectedWaitingForMap) to(ConnectedDownloadingMap)

and won't change to any other state. Trying to start singleplayer game or exit cause game crash.

[Smarty]

Hello.

Same problem here.
Headless server and user is on latest 0.14.21. Other users didn't have any problem with initial connection to server (but from time to time have problems with desyncs - other story) but I can not normally connect to server: I need restart Factorio one-ten-twenty times before it can download map and login to server. Server restart can also solve my connection problem, but not always.

Server admin and I can not determine exacly source of problem but problem exist.

Connection to server is successfull, map started download at full 100 Mbit/s speed as should, download proceed to the end of progress bar and then speed is fall to 0 bit/s in about 2-3s and stay in this position forever. Factorio is in download map state (as stated in log:

40.808 Info ClientMultiplayerManager.cpp:669: Received mapReadyForDownload
40.808 Downloading file C:\Users\umka\AppData\Roaming\Factorio\temp\mp-download.zip (31713568 B, 63049 blocks)
40.812 Info ClientMultiplayerManager.cpp:539: MapTick(-1) changing state from(ConnectedWaitingForMap) to(ConnectedDownloadingMap)

Could you please provide the full log?

[dadymax]

at 46.935 I was clicked on CLOSE cross - Factorio shutdown properly.

Code: Select all

0.001 2017-01-05 15:25:29; Factorio 0.14.21 (build 25327, win64, steam)
   0.001 Operating system: Windows 10 (version 1511) 
   0.001 Program arguments: "F:\!Games\Steam\steamapps\common\Factorio\bin\x64\Factorio.exe" 
   0.001 Read data path: F:/!Games/Steam/steamapps/common/Factorio/data
   0.001 Write data path: C:/Users/umka/AppData/Roaming/Factorio
   0.001 Binaries path: F:/!Games/Steam/steamapps/common/Factorio/bin
   0.012 System info: [CPU:         Intel(R) Core(TM) i7-3770 CPU @ 3.40GHz, 8 cores, RAM: 24452MB]
   0.013 Display options: [FullScreen: 0] [VSync: 0] [UIScale: 100%] [MultiSampling: OFF] [Screen: 255]
   0.016 Available display adapters: 2
   0.016  [0]: \\.\DISPLAY1 - NVIDIA GeForce GTX 770 {0x05, [0,0], 1920x1080, 32bit, 60Hz}
   0.016  [1]: \\.\DISPLAY2 - NVIDIA GeForce GTX 770 {0x01, [1920,0], 1920x1080, 32bit, 60Hz}
   0.016 Create display on adapter 0. Size 1280x720 at position [310, 162].
   0.053 Initialised Direct3D:[0] NVIDIA GeForce GTX 770; driver: nvd3dumx.dll 10.18.13.6881
   0.056     Video memory size (dedicated video/dedicated system/shared system/available): 2017/0/12226/4092 MB
   0.087 DSound: Starting _dsound_update thread
   0.087 DSound: Enter _dsound_update; tid=5092
   0.089 Device reset internal.
   0.091 Desktop composition is active.
   0.092 Graphics options: [Graphics quality: normal] [Video memory usage: high] [Light scale: 30%] [DXT: false]
   0.238 Info ModManager.cpp:93: Found duplicate mod rso-mod, using higher version (2.2.9 > 2.2.7).
   0.276 Loading mod core 0.0.0 (data.lua)
   0.280 Loading mod base 0.14.21 (data.lua)
   0.363 Loading mod what-is-it-used-for 1.1.5 (data.lua)
   0.416 Loading mod 5dim_core 0.14.1 (data.lua)
   0.472 Loading mod advanced-logistics-system 0.4.0 (data.lua)
   0.527 Loading mod air-filtering 0.4.3 (data.lua)
   0.588 Loading mod AlienArtifacts 0.1.2 (data.lua)
   0.644 Loading mod AllFluids 1.0.3 (data.lua)
   0.708 Loading mod boblibrary 0.14.3 (data.lua)
   0.764 Loading mod CORE-DyTech-Core 3.0.5 (data.lua)
   0.831 Loading mod ElectricVoid 1.0.8 (data.lua)
   0.900 Loading mod Fluid Void 1.0.4 (data.lua)
   0.956 Loading mod Large-Chests 14.0.13 (data.lua)
   1.018 Loading mod MAIN-DyTech-Dynamics 3.0.5 (data.lua)
   1.091 Loading mod motrans 0.2.11 (data.lua)
   1.148 Loading mod Nucular 1.0.4 (data.lua)
   1.211 Loading mod Reactors 1.5.1 (data.lua)
   1.286 Loading mod skan-radio-telemetry 1.0.1 (data.lua)
   1.349 Loading mod SmartSplitters 1.0.1 (data.lua)
   1.422 Loading mod VoidChestInstant 1.0.2 (data.lua)
   1.485 Loading mod Warehousing 0.0.11 (data.lua)
   1.551 Loading mod yi_railway 0.4.13 (data.lua)
   1.644 Loading mod Yuoki 0.4.61 (data.lua)
   1.748 Loading mod 5dim_automatization 0.14.0 (data.lua)
   1.869 Loading mod 5dim_energy 0.14.0 (data.lua)
   1.973 Loading mod 5dim_logistic 0.14.1 (data.lua)
   2.081 Loading mod 5dim_mining 0.14.0 (data.lua)
   2.215 Loading mod 5dim_resources 0.14.0 (data.lua)
   2.320 Loading mod 5dim_transport 0.14.0 (data.lua)
   2.442 Loading mod 5dim_vehicle 0.14.0 (data.lua)
   2.562 Loading mod Arborium 0.0.4 (data.lua)
   2.704 Loading mod MAIN-DyTech-Metallurgy 3.0.3 (data.lua)
   2.822 Loading mod mopower 0.5.21 (data.lua)
   2.947 Loading mod yi_engines 0.4.19 (data.lua)
   3.115 Loading mod z_yira_american 0.4.6 (data.lua)
   3.238 Loading mod z_yira_UP 0.4.6 (data.lua)
   3.372 Loading mod z_yira_yuokirails 0.4.6 (data.lua)
   3.534 Loading mod MAIN-DyTech-Machine 3.0.4 (data.lua)
   3.705 Loading mod MAIN-DyTech-Power 3.0.3 (data.lua)
   3.889 Loading mod MAIN-DyTech-War 3.0.5 (data.lua)
   4.100 Loading mod SpaceBook 1.0.23 (data.lua)
   4.291 Loading mod CORE-DyTech-Core 3.0.5 (data-updates.lua)
   4.538 Loading mod MAIN-DyTech-Dynamics 3.0.5 (data-updates.lua)
   4.762 Loading mod Arborium 0.0.4 (data-updates.lua)
   5.045 Loading mod MAIN-DyTech-Metallurgy 3.0.3 (data-updates.lua)
   5.295 Loading mod steinios_Reactors_patch 0.14.2 (data-updates.lua)
   5.551 Loading mod MAIN-DyTech-Machine 3.0.4 (data-updates.lua)
   5.864 Loading mod MAIN-DyTech-Power 3.0.3 (data-updates.lua)
   6.128 Loading mod MAIN-DyTech-War 3.0.5 (data-updates.lua)
   6.381 Loading mod rso-mod 2.2.9 (data-updates.lua)
   6.644 Loading mod CORE-DyTech-Core 3.0.5 (data-final-fixes.lua)
   6.973 Loading mod MAIN-DyTech-Metallurgy 3.0.3 (data-final-fixes.lua)
   7.221 Loading mod MAIN-DyTech-War 3.0.5 (data-final-fixes.lua)
   7.481 Loading mod Yi_Tech_Tree 0.14.12 (data-final-fixes.lua)
   7.808 Checksum for core: 1291735968
   7.808 Checksum for mod base: 786624017
   7.808 Checksum for mod what-is-it-used-for: 3913150713
   7.808 Checksum for mod 5dim_core: 4109024274
   7.808 Checksum for mod advanced-logistics-system: 2163846892
   7.808 Checksum for mod air-filtering: 2717869336
   7.808 Checksum for mod AlienArtifacts: 3285837088
   7.808 Checksum for mod AllFluids: 1324556902
   7.808 Checksum for mod boblibrary: 3645220963
   7.808 Checksum for mod clock: 0
   7.808 Checksum for mod CORE-DyTech-Core: 2825521336
   7.808 Checksum for mod ElectricVoid: 3130819401
   7.808 Checksum for mod Fluid Void: 1461162325
   7.808 Checksum for mod Large-Chests: 716506111
   7.808 Checksum for mod MAIN-DyTech-Dynamics: 2387869385
   7.808 Checksum for mod motrans: 1766468243
   7.808 Checksum for mod Nucular: 483423969
   7.808 Checksum for mod Reactors: 404802149
   7.808 Checksum for mod skan-radio-telemetry: 1815454241
   7.808 Checksum for mod SmartSplitters: 2283819806
   7.808 Checksum for mod VoidChestInstant: 798133373
   7.808 Checksum for mod Warehousing: 3149064619
   7.808 Checksum for mod yi_railway: 3254591468
   7.809 Checksum for mod Yuoki: 2930266198
   7.809 Checksum for mod 5dim_automatization: 567552077
   7.809 Checksum for mod 5dim_energy: 3811993497
   7.809 Checksum for mod 5dim_logistic: 3113580193
   7.809 Checksum for mod 5dim_mining: 2164630453
   7.809 Checksum for mod 5dim_resources: 2219748488
   7.809 Checksum for mod 5dim_transport: 2221020352
   7.809 Checksum for mod 5dim_vehicle: 357293043
   7.809 Checksum for mod Arborium: 1671624045
   7.809 Checksum for mod MAIN-DyTech-Metallurgy: 288730485
   7.809 Checksum for mod mopower: 2870492672
   7.809 Checksum for mod steinios_Reactors_patch: 1286471049
   7.809 Checksum for mod yi_engines: 1549495814
   7.809 Checksum for mod z_yira_american: 1215416967
   7.809 Checksum for mod z_yira_UP: 170838772
   7.809 Checksum for mod z_yira_yuokirails: 2437188739
   7.809 Checksum for mod MAIN-DyTech-Machine: 2679420870
   7.809 Checksum for mod MAIN-DyTech-Power: 1871285636
   7.809 Checksum for mod MAIN-DyTech-War: 352704748
   7.809 Checksum for mod Yi_Tech_Tree: 4271468889
   7.809 Checksum for mod rso-mod: 1617313105
   7.809 Checksum for mod SpaceBook: 988214470
   9.264 Info PlayerData.cpp:55: Local player-data.json available, timestamp 1483618798
   9.264 Info PlayerData.cpp:62: Cloud player-data.json unavailable
   9.594 Initial atlas bitmap size is 16384
   9.597 Created atlas bitmap 16384x12464
  10.040 Created atlas bitmap 4096x1168
  10.045 Created atlas bitmap 4096x3648
  29.548 Sprites loaded
  29.548 Convert atlas 4096x1168 to: trilinear-filtering 
  29.563 Convert atlas 4096x3648 to: mipmap 
  29.901 Loading sounds...
  31.170 Custom inputs active: 3
  31.202 Factorio initialised
  37.531 Joining game 213.141.140.29:34197
  37.531 Info UDPSocket.cpp:33: Opening socket
  37.531 Verbose RouterBase.cpp:37: Started router thread.
  37.532 Info ClientMultiplayerManager.cpp:539: MapTick(-1) changing state from(Ready) to(Connecting)
  37.574 Connection refused
  37.574 Info ClientMultiplayerManager.cpp:177: Quitting multiplayer connection.
  37.574 Info ClientMultiplayerManager.cpp:539: MapTick(-1) changing state from(Connecting) to(Disconnected)
  37.670 Verbose RouterBase.cpp:48: Finishing router thread.
  37.670 Info UDPSocket.cpp:235: Socket closed
  38.844 Joining game 213.141.140.29:34197
  38.844 Info UDPSocket.cpp:33: Opening socket
  38.845 Verbose RouterBase.cpp:37: Started router thread.
  38.845 Info ClientMultiplayerManager.cpp:539: MapTick(-1) changing state from(Ready) to(Connecting)
  38.874 Info ClientSynchronizer.cpp:34: Initialized Synchronizer local peer(1) latency(32).
  38.875 Info ClientMultiplayerManager.cpp:539: MapTick(-1) changing state from(Connecting) to(ConnectedWaitingForMap)
  38.875 Info ClientRouter.cpp:219: ConnectionAccepted
  40.808 Info ClientMultiplayerManager.cpp:669: Received mapReadyForDownload
  40.808 Downloading file C:\Users\umka\AppData\Roaming\Factorio\temp\mp-download.zip (31713568 B, 63049 blocks)
  40.812 Info ClientMultiplayerManager.cpp:539: MapTick(-1) changing state from(ConnectedWaitingForMap) to(ConnectedDownloadingMap)
  46.935 Info ClientMultiplayerManager.cpp:129: Disconnecting multiplayer connection.
  46.935 Info ClientMultiplayerManager.cpp:539: MapTick(-1) changing state from(ConnectedDownloadingMap) to(DisconnectScheduled)
  46.969 Info ClientMultiplayerManager.cpp:539: MapTick(-1) changing state from(DisconnectScheduled) to(WaitingForDisconnectConfirmation)
  50.268 Info ClientMultiplayerManager.cpp:539: MapTick(-1) changing state from(WaitingForDisconnectConfirmation) to(Disconnected)
  50.821 Info UDPSocket.cpp:235: Socket closed
  50.954 DSound: Stopping voice
  50.954 DSound: Joining thread
  50.957 DSound: Exit _dsound_update; tid=5092
  50.957 DSound: Waiting for voice to stop ... signaled
  50.957 DSound: Joined thread
  50.957 DSound: Destroying thread
  50.957 DSound: Thread destroyed
  50.957 DSound: Releasing buffer
  50.957 DSound: Voice stopped
  50.957 DSound: Deallocating voice
  50.957 DSound: Deallocated voice
  50.987 Steam API shutdown.
  50.989 Goodbye

[Loewchen]

Try the executable provided here: viewtopic.php?f=182&t=33163, and please post the results with explanation in that report.

[dadymax]

Try the executable provided here: viewtopic.php?f=182&t=33163, and please post the results with explanation in that report.

np.
added zipped log because of ~45Mb unpacked size.
Started factorio-run.exe, Play -> Multiplayer -> Connect to server -> Connect -> enter password -> Connect -> Download started -> I wait until progres bar go to the end and some time after (speed goes down to 0 at the end) -> click to CROSS -> programm closed properly.

Another idea: there are some race condition appear because with this heavy debug version I have success on connection more frequently: from five tries two was successfull.

[dadymax]

Offtop.
Well, with this debug version after few tries I can play some time but another glitch happen: sudden server connection lost. Nothing unusual happen. Even more - I can stay still and nothing do at all and server connection loss occurs. Meanwhile my friends continue build things on same server without me. Log from debug version attached.

Because some sort of that bad things occur from 0.11.x I suppose that this can be related to ISP... That would be pretty bad...

[Twinsen]

Thanks for the logs dadymax.
So based on the logs, the same 2 packets seem to get lost over and over again forever

Code: Select all

 104.443 Info TransferTarget.cpp:235: Lost block 2955 (RTO at 0.500000 seconds)
 104.443 Info TransferTarget.cpp:140: Requesting block(2955)

 104.493 Info TransferTarget.cpp:235: Lost block 10301 (RTO at 0.500000 seconds)
 104.493 Info TransferTarget.cpp:140: Requesting block(10301)

This happens 1000+ times.
This is very odd. It's like some firewall is blocking that specific data.

Is the server local? (I see 5ms response time to server)
Do you have easy access to the server, or can you reproduce this issue with your own server?
Does this happen only in headless or with normal server also?
Please redo the test(with the special exe) and also upload the server logs.
I will investigate the server logs and if I don't see any problem I will make another executable that does more logging on the server side too.

Thanks for the help.

[dadymax]

Thanks for the logs dadymax.
Is the server local? (I see 5ms response time to server)
Do you have easy access to the server, or can you reproduce this issue with your own server?
Does this happen only in headless or with normal server also?
Please redo the test(with the special exe) and also upload the server logs.
I will investigate the server logs and if I don't see any problem I will make another executable that does more logging on the server side too.

Thanks for the help.

Thanks for awesome game. Even with these annoying glitches it is still very enjoyable!

For your questions:
Server is on other ISP in my city (Russia-Moscow).
Server admin is my friend and yes, we can have access to the server. I does not try reproduce this on my own server (will think about it when have time, there is a lot to do on current game, you know... )
This happen with headless and headfull version of server (on the same admin hardware but on distinct PC).
Currently server run under Ubuntu but I'll ask admin to run it from win-PC to do the test. I will post results as fast as I can.

Thanks for your patience!

[dadymax]

Well, tests are done.
1. On my own server I have not any problem with connection.
2. Admin of the server move server to win and run special-exe. After few tries we successfully catch this bug - logs attached.

Two test series was done. Server side on last run was cropped to only my connection log.

dadymax_downloadbug_win_factorio-current_client_1.log
dadymax_downloadbug_win_factorio-current_client_2.log
dadymax_downloadbug_win_factorio-current_server.log
dadymax_downloadbug_win_factorio-current_server_2.log

Adn other thing: on this server we play several years in many games and have not any problem with connection (Minecraft as example). Because of this I think problem is in "tcp over udp" or something...

[Twinsen]

Thank you very much for your help.
Unfortunately there is nothing relevant in the server log. Some specific packet seems to get blocked. I made another version that does complete logging on the server also. This way we will find out if the packet get lost from client to server or from server to client.
Run this executable on both the client and server and send the logs as before.

Factorio_0.14.21 TransferTargetSource Logging.zip

(47.29 MiB) Downloaded 309 times

We have some theory of what might happen(basically your firewall, router or ISP is blocking or modifying packets with some specific format and content). This would be quite absurd, but I made a version that will put some random junk data in the map transfer requests to try to counter this.
Same thing, run this executable on both the client and server and send the logs as before.

Factorio_0.14.21 Fix attempt+TransferTargetSource Logging.zip

(47.3 MiB) Downloaded 653 times

Your help is appreciated.

[dadymax]

We have some theory of what might happen(basically your firewall, router or ISP is blocking or modifying packets with some specific format and content). This would be quite absurd, but I made a version that will put some random junk data in the map transfer requests to try to counter this.
Same thing, run this executable on both the client and server and send the logs as before.

The attachment Factorio_0.14.21 Fix attempt+TransferTargetSource Logging.zip is no longer available

Your help is appreciated.

From first connect try bug was catched. Logs attached. We run client and server with second variant. I think that run with first debug version won't be more informative.

[Twinsen]

Based on the log, the client requests a packet, it gets through, the server receives it and then sends a small block of the map in a packet. And this packet is never received by the client, not even malformed. The same map block gets lost over and over again so my best guess still remains, that your ISP(or more probably the server's ISP) is looking inside the packet and filtering it thinking it's probably some blocked VoIP service or something.

Try experimenting with different port values by changing "port=" in \Factorio\config\config.ini.

I did a similar thing as last time and added a byte of random data to the server map packets to try and trick your ISP, but with a large packet with binary data, it might not be so helpful.
This version will also log all the traffic that gets sent on the socket so expect some large log files.
Note that you need to replace both the client and the server executable with this one:

Factorio_0.14.21 Fix attempt+TransferTargetSource Logging 2.zip

(47.28 MiB) Downloaded 341 times

Running this multiple times would be helpful since I can extract multiple blocked packets and possibly look for a pattern.
This is still mostly theory, I could just be horribly wrong

[dadymax]

Based on the log, the client requests a packet, it gets through, the server receives it and then sends a small block of the map in a packet. And this packet is never received by the client, not even malformed. The same map block gets lost over and over again so my best guess still remains, that your ISP(or more probably the server's ISP) is looking inside the packet and filtering it thinking it's probably some blocked VoIP service or something.

Try experimenting with different port values by changing "port=" in \Factorio\config\config.ini.

I did a similar thing as last time and added a byte of random data to the server map packets to try and trick your ISP, but with a large packet with binary data, it might not be so helpful.
This version will also log all the traffic that gets sent on the socket so expect some large log files.

The attachment Factorio_0.14.21 Fix attempt+TransferTargetSource Logging 2.zip is no longer available

Running this multiple times would be helpful since I can extract multiple blocked packets and possibly look for a pattern.
This is still mostly theory, I could just be horribly wrong

Well, with this random data you forgot to notify client about it... Client cannot download map at all (hangs at 0 byte) and in logs there are lines like:

Code: Select all

  98.512 Info TransferTarget.cpp:173: Received block -1124073472 that we didn't request 

But for consistence I attached logs from client and server. And yes - port was changed to some non standart serveral times - no effect.
Tomorrow I wil try set sniffer on my own router to see what happpen in down-link at time when bug happen.