[Oxyd] [0.17.55] Reading stdin failed [Linux headless]

[grilledham]

I host multiple servers and for these servers I communicate with factorio using stdin / stdout, for example to link game chat with discord chat.

Since 0.17.53 I keep getting errors with broken pipes when trying to send messages to factorio using stdin. The pipe seems to break typically 6 - 12 hours after the process starts, which makes it hard to identify a cause. The only message that appears in the Factroio logs is

Code: Select all

Error InterruptibleStdioStream.cpp:54: Reading stdin failed

When stdin fails, stdout still works without problems. I've attached the log in case there is any useful information.

Prior to 0.17.53 I hosted multiple servers for over 9 months without encountering a broken pipe, so I have to think that maybe something changed on the Factorio side.

Unfortunately I'm not really sure what is causing the problem, so I am not sure if I can provide more useful information, but if you need more feel free to ask.

[Gerkiz]

Hello,
I also have this issue.

I host also multiple servers where I see this issue in the logs.

Code: Select all

46774.905 Info AppManager.cpp:257: Saving finished
47027.856 Info ServerRouter.cpp:616: Asking pingpong servers (pingpong1.factorio.com:34197, pingpong2.factorio.com:34197, pingpong3.factorio.com:34197, pingpong4.factorio.com:34197) for own address
47027.955 Info ServerRouter.cpp:495: Own address is IP ADDR:({:32101}) (confirmed by pingpong1)
47027.980 Info ServerRouter.cpp:495: Own address is IP ADDR:({:32101}) (confirmed by pingpong3)
47028.155 Info ServerRouter.cpp:495: Own address is IP ADDR:({:32101}) (confirmed by pingpong4)
47148.029 Info ChildProcessAgent.cpp:60: Child 21400 exited with return value 0
47148.204 Error InterruptibleStdioStream.cpp:54: Reading stdin failed

[Rseding91]

No idea what would cause this but the specific file which handles reading stdin (InterruptibleStdioStream) hasn't been changed in the last 4 months.

[mark9064]

Also experiencing this at explosivegaming:

It seems to be recent though I do not know the exact version when it broke (could it be to do with the rcon packet fragmentation stuff somehow)

Code: Select all

15000.729 Info ServerSynchronizer.cpp:619: nextHeartbeatSequenceNumber(425382) removing peer(13).
15132.405 Info AppManager.cpp:256: Saving to _autosave7 (non-blocking).
15132.414 Info AsyncScenarioSaver.cpp:144: Saving process PID: 18922
15133.283 Info ChildProcessAgent.cpp:60: Child 18922 exited with return value 0
15133.283 Info AppManager.cpp:257: Saving finished
15210.783 Info ChildProcessAgent.cpp:60: Child 18943 exited with return value 0
15210.789 Error InterruptibleStdioStream.cpp:54: Reading stdin failed
15249.849 Info RemoteCommandProcessor.cpp:237: New RCON connection from IP ADDR:({0.0.0.0:0})
15549.862 Info RemoteCommandProcessor.cpp:237: New RCON connection from IP ADDR:({0.0.0.0:0})

[grilledham]

I have a bunch more log files where stdin has failed which I have attached.

I would like to draw attention to factorio-current (1).log which contains this

Code: Select all

   4.103 Info ChildProcessAgent.cpp:60: Child 11684 exited with return value 0
   4.332 code:35, 23; error:1408F10B:SSL routines:ssl3_get_record:wrong version number
   4.532 Error InterruptibleStdioStream.cpp:54: Reading stdin failed

I also keep chat logs for my servers and at the same time the server spammed chat with:

Code: Select all

2019-07-11 05:12:54 [SERVER-STARTED]
2019-07-11 05:12:58 <server>:  f  b]&�Y]񞽱�l��y��ɦ�PT�^�U�G l�n��-(�zZ�`��A�~H��`SuPF�$?>
2019-07-11 05:12:58 <server>:  
2019-07-11 05:12:58 <server>:  
2019-07-11 05:12:58 <server>:  m0�i0�Q��^5�S:�J�{��K0
2019-07-11 05:12:58 <server>: 
2019-07-11 05:12:58 <server>: � ��!'����'!�
2019-07-11 05:12:58 <server>: �B����\��hX��>� ׆e��D?�g&�kGI��
2019-07-11 05:12:58 <server>: ��J�aLÂ��\�^�Y:��XX��(?'�, �>�B[�z:O�}8#H&��r)V�����S3(�;��(��d.���:4�=�d�%́`���s�
2019-07-11 05:12:58 <server>: ����aB���0��]tVd��jRI�˚_��5�[��X� ��n0�j0U��0U%0++0U�0 0U�(�f�q�U7L��hJ��0U#0��Jjc}ݺ��9��Ee���0o+c0a0.+0�"http://ocsp.int-x3.letsencrypt.org0/+0�#http://cert.int-x3.letsencrypt.org/0#U0�multiplayer.factorio.com0LU E0C0g�07+��0(0&+http://cps.letsencrypt.org0�
2019-07-11 05:12:58 <server>: +�y���� � w �iK�&��@	��;��>��t����(�  jҎ��   H0F! ��	<āEo�%�L ��@��r
2019-07-11 05:12:58 <server>: ���Wi4�-! �UN�d��Y��76���E�)�4n���d`�
2019-07-11 05:12:58 <server>: 4 v c����;�,�r�'Wk3��aw��u�8��hTK؍  jҎ��   G0E T��U3��y3%��-:�He�q�h�}���! Ė m��Wp��Rv���{�Տ��Y�T�M<���P0
2019-07-11 05:12:58 <server>: �r�z0���7{Uc��U�tk4����0oPTt��8K��M�L38�`�
2019-07-11 05:12:58 <server>: AB  S�sj��0
2019-07-11 05:12:58 <server>: Digital Signature Trust Co.10UDST Root CA X30
2019-07-11 05:12:58 <server>: 
2019-07-11 05:12:58 <server>: � ���Z�.G�r]7��hc0��5&%὾5�p�/��KA���5X�*�h���u���bq�y�`ב����xgq�i������`<H�~�Mw$�GZ��7 ��{���J�A�6����m<�h�#*B��tg����Ra?e邇���V����?������k
2019-07-11 05:12:58 <server>: H����eb��T�*� ��������2���w��ye+�(�:R��R._���3�wl�@�2��\A�tl[]
2019-07-11 05:12:58 <server>: _3�M��8�/{,b�٣�o%/��F=�~�z���zm�%�����/X�/,h&�K��ڟ���CJDNosz(ꤪn{L}����D����4[�BM I A�d����JT4�J�~�^c4s�8�j��CG='���<t����b6ᗡ@�뀖�k�`�`� ;� �O0�&x��	��Jn
2019-07-11 05:12:58 <server>: �%

Full chat log also attached (chat-current.log).

[mrvn]

Code: Select all

Error InterruptibleStdioStream.cpp:54: Reading stdin failed

InterruptibleStdioStream sounds like it will abort reading when it gets a signal at the same time. Even if it reads only when input is present this can still happen. This could simply be a case of the read failing with EINTR. Any chance of outputing the low-level error when it fails?

[grilledham]

Sorry I don't know what EINTR is.

In my experience when factorio receives a signal it logs it, for example something like this:

Code: Select all

62863.961 Received SIGTERM, shutting down

So I don't think a signal was received at the same time.

[mrvn]

There surely are a lot of signals where factorio does not have a signal handler that outputs a message for. The SIGTERM is special because factorio catches that signal and shuts down gracefully. Other signals won't have that effect and there might be signals not used by factorio itself at all but rather use by one of the libraries factorio uses.

[Oxyd]

I have a bunch more log files where stdin has failed which I have attached.

I would like to draw attention to factorio-current (1).log which contains this

Code: Select all

   4.103 Info ChildProcessAgent.cpp:60: Child 11684 exited with return value 0
   4.332 code:35, 23; error:1408F10B:SSL routines:ssl3_get_record:wrong version number
   4.532 Error InterruptibleStdioStream.cpp:54: Reading stdin failed

I also keep chat logs for my servers and at the same time the server spammed chat with:

Code: Select all

2019-07-11 05:12:54 [SERVER-STARTED]
2019-07-11 05:12:58 <server>:  f  b]&�Y]񞽱�l��y��ɦ�PT�^�U�G l�n��-(�zZ�`��A�~H��`SuPF�$?>
2019-07-11 05:12:58 <server>:  
2019-07-11 05:12:58 <server>:  
2019-07-11 05:12:58 <server>:  m0�i0�Q��^5�S:�J�{��K0
2019-07-11 05:12:58 <server>: 
2019-07-11 05:12:58 <server>: � ��!'����'!�
2019-07-11 05:12:58 <server>: �B����\��hX��>� ׆e��D?�g&�kGI��
2019-07-11 05:12:58 <server>: ��J�aLÂ��\�^�Y:��XX��(?'�, �>�B[�z:O�}8#H&��r)V�����S3(�;��(��d.���:4�=�d�%́`���s�
2019-07-11 05:12:58 <server>: ����aB���0��]tVd��jRI�˚_��5�[��X� ��n0�j0U��0U%0++0U�0 0U�(�f�q�U7L��hJ��0U#0��Jjc}ݺ��9��Ee���0o+c0a0.+0�"http://ocsp.int-x3.letsencrypt.org0/+0�#http://cert.int-x3.letsencrypt.org/0#U0�multiplayer.factorio.com0LU E0C0g�07+��0(0&+http://cps.letsencrypt.org0�
2019-07-11 05:12:58 <server>: +�y���� � w �iK�&��@	��;��>��t����(�  jҎ��   H0F! ��	<āEo�%�L ��@��r
2019-07-11 05:12:58 <server>: ���Wi4�-! �UN�d��Y��76���E�)�4n���d`�
2019-07-11 05:12:58 <server>: 4 v c����;�,�r�'Wk3��aw��u�8��hTK؍  jҎ��   G0E T��U3��y3%��-:�He�q�h�}���! Ė m��Wp��Rv���{�Տ��Y�T�M<���P0
2019-07-11 05:12:58 <server>: �r�z0���7{Uc��U�tk4����0oPTt��8K��M�L38�`�
2019-07-11 05:12:58 <server>: AB  S�sj��0
2019-07-11 05:12:58 <server>: Digital Signature Trust Co.10UDST Root CA X30
2019-07-11 05:12:58 <server>: 
2019-07-11 05:12:58 <server>: � ���Z�.G�r]7��hc0��5&%὾5�p�/��KA���5X�*�h���u���bq�y�`ב����xgq�i������`<H�~�Mw$�GZ��7 ��{���J�A�6����m<�h�#*B��tg����Ra?e邇���V����?������k
2019-07-11 05:12:58 <server>: H����eb��T�*� ��������2���w��ye+�(�:R��R._���3�wl�@�2��\A�tl[]
2019-07-11 05:12:58 <server>: _3�M��8�/{,b�٣�o%/��F=�~�z���zm�%�����/X�/,h&�K��ڟ���CJDNosz(ꤪn{L}����D����4[�BM I A�d����JT4�J�~�^c4s�8�j��CG='���<t����b6ᗡ@�뀖�k�`�`� ;� �O0�&x��	��Jn
2019-07-11 05:12:58 <server>: �%

Full chat log also attached (chat-current.log).

Very interesting. I also see that for you it happened four seconds after starting the server – was that just luck or can you somehow reproduce it?

[grilledham]

Very interesting. I also see that for you it happened four seconds after starting the server – was that just luck or can you somehow reproduce it?

I think that was just bad luck, I have not been able to reliably reproduce it in test conditions. But it happens about twice per day for my real servers.

The only thing I've noticed from the logs is that it always seems to be preceded by a message like this.

Code: Select all

4.103 Info ChildProcessAgent.cpp:60: Child 11684 exited with return value 0

But I don't know what ChildProcessAgent does.

[Oxyd]

Are you, by any chance, using an HTTP proxy? As in, is it possible that Factorio connects to the matching server through a proxy? One with NTLM authentication, even?

[Gerkiz]

Hello,
To update on this, it seems that this started happening on 2019-07-02, the day after 0.17.53 was released.

The first log from 2019-07-01 is clean of broken pipes.
The other log from 2019-07-02 starts at 05:28, roughly 4 hours after the game was started.

[grilledham]

Are you, by any chance, using an HTTP proxy? As in, is it possible that Factorio connects to the matching server through a proxy? One with NTLM authentication, even?

I also host a web server on the same machine that uses nginx as a reverse proxy. But as far as I'm aware the Factorio processes shouldn't be using a proxy.

[grilledham]

I've been playing around with this issue and may have found a way to reproduce it, or at least a similar issue.
If I run the freeplay scenario with this server-settings.json:

Code: Select all

{
  "name": "",
  "description": "",
  "tags": [    
  ],
  "max_players": 0,
  "visibility": {
    "public": true,
    "lan": true
  },
  "autosave_interval": 1,
  "autosave_slots": 1,
  "non_blocking_saving": false,
  "auto_pause": false,
  "autosave_only_on_server": true,
  "username": "use your own",
  "token": "use your own",
  "game_password": "some password to stop people joining",
  "require_user_verification": true,
  "max_upload_in_kilobytes_per_second": 0.0,
  "max_upload_slots": 32,
  "minimum_latency_in_ticks": 0,
  "ignore_player_limit_for_returning_players": false,
  "allow_commands": "admins-only",  
  "afk_autokick_interval": 0,  
  "use_default_admins": true,
  "only_admins_can_pause_the_game": true  
}

And set game speed to 100.
After about 10-15 minutes stdin fails.
I've attached 2 logs where it happens.
In these cases the error message is slightly different

Code: Select all

Error InterruptibleStdioStream.cpp:63: Reading stdin failed (9): Bad file descriptor

[Oxyd]

Well, thanks for the information, everyone. I think I've managed to fix it.

To implement asynchronous saving, we fork the Factorio process, create a pipe between the child and the parent, and associate the pipe's FDs with the child PID. When the child exits, ChildProcessAgent closes the pipe.

What happens here, though, is that something else forks the process, so we now have a child but no pipe FD associated with its PID. When the child exits, the game still tries to close the pipe – which results in it closing file descriptor 0. This is of course stupidly trivial to fix.

Only mystery that remains is what forks the game. It's not our code, so it must be one of the libraries we're using. About the only plausible candidate I've found is libcurl, which forks and execs as a part of its NTLM authentication routine. Hence the question about the proxies.

I'm not quite sure why it would start failing now, though. Or why anyone would run a Factorio server behind an HTTP proxy, for that matter.

But, either way, fixed in 0.17.57.

[grilledham]

The last two logs I uploaded use non-asynchronous or blocking saving. Is the problem likely fixed for blocking saving too?

[Oxyd]

The last two logs I uploaded use non-asynchronous or blocking saving. Is the problem likely fixed for blocking saving too?

Yes.

[grilledham]

OK, thanks.

[mrvn]

Well, thanks for the information, everyone. I think I've managed to fix it.

To implement asynchronous saving, we fork the Factorio process, create a pipe between the child and the parent, and associate the pipe's FDs with the child PID. When the child exits, ChildProcessAgent closes the pipe.

What happens here, though, is that something else forks the process, so we now have a child but no pipe FD associated with its PID. When the child exits, the game still tries to close the pipe – which results in it closing file descriptor 0. This is of course stupidly trivial to fix.

Only mystery that remains is what forks the game. It's not our code, so it must be one of the libraries we're using. About the only plausible candidate I've found is libcurl, which forks and execs as a part of its NTLM authentication routine. Hence the question about the proxies.

I'm not quite sure why it would start failing now, though. Or why anyone would run a Factorio server behind an HTTP proxy, for that matter.

But, either way, fixed in 0.17.57.

I hope you are using O_CLOEXEC so you aren't leaking FDs to the NTLM authentication routine.