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

This subforum contains all the issues which we already resolved.
Post Reply
grilledham
Inserter
Inserter
Posts: 21
Joined: Tue Sep 25, 2018 9:32 pm
Contact:

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

Post by grilledham » Wed Jul 10, 2019 11:16 am

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.
Attachments
factorio-current.log
(57.07 KiB) Downloaded 23 times

User avatar
Gerkiz
Burner Inserter
Burner Inserter
Posts: 7
Joined: Fri Nov 30, 2018 3:36 pm
Contact:

Re: [0.17.55] Reading stdin failed

Post by Gerkiz » Wed Jul 10, 2019 11:51 am

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
Attachments
factorio-current.log
(418.41 KiB) Downloaded 18 times

Rseding91
Factorio Staff
Factorio Staff
Posts: 9974
Joined: Wed Jun 11, 2014 5:23 am
Contact:

Re: [0.17.55] Reading stdin failed

Post by Rseding91 » Wed Jul 10, 2019 12:00 pm

No idea what would cause this but the specific file which handles reading stdin (InterruptibleStdioStream) hasn't been changed in the last 4 months.
If you want to get ahold of me I'm almost always on Discord.

mark9064
Burner Inserter
Burner Inserter
Posts: 5
Joined: Sun Feb 11, 2018 11:23 am
Contact:

Re: [0.17.55] Reading stdin failed [Linux headless]

Post by mark9064 » Wed Jul 10, 2019 12:36 pm

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
Inserter
Inserter
Posts: 21
Joined: Tue Sep 25, 2018 9:32 pm
Contact:

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

Post by grilledham » Thu Jul 11, 2019 10:37 am

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).
Attachments
chat-current.log
(44.21 KiB) Downloaded 13 times
factorio-current (1).log
(182.2 KiB) Downloaded 17 times
factorio-current.log
(110.31 KiB) Downloaded 14 times
factorio-current20190711101524.log
(70.45 KiB) Downloaded 13 times
factorio-current20190711101510.log
(43.3 KiB) Downloaded 16 times
factorio-current20190711101552.log
(61.61 KiB) Downloaded 16 times

mrvn
Smart Inserter
Smart Inserter
Posts: 3853
Joined: Mon Sep 05, 2016 9:10 am
Contact:

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

Post by mrvn » Thu Jul 11, 2019 10:50 am

grilledham wrote:
Wed Jul 10, 2019 11:16 am

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
Inserter
Inserter
Posts: 21
Joined: Tue Sep 25, 2018 9:32 pm
Contact:

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

Post by grilledham » Thu Jul 11, 2019 11:04 am

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
Smart Inserter
Smart Inserter
Posts: 3853
Joined: Mon Sep 05, 2016 9:10 am
Contact:

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

Post by mrvn » Thu Jul 11, 2019 11:38 am

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
Factorio Staff
Factorio Staff
Posts: 1296
Joined: Thu May 07, 2015 8:42 am
Contact:

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

Post by Oxyd » Fri Jul 12, 2019 10:08 am

grilledham wrote:
Thu Jul 11, 2019 10:37 am
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
Inserter
Inserter
Posts: 21
Joined: Tue Sep 25, 2018 9:32 pm
Contact:

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

Post by grilledham » Fri Jul 12, 2019 10:37 am

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
Factorio Staff
Factorio Staff
Posts: 1296
Joined: Thu May 07, 2015 8:42 am
Contact:

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

Post by Oxyd » Fri Jul 12, 2019 2:10 pm

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?

User avatar
Gerkiz
Burner Inserter
Burner Inserter
Posts: 7
Joined: Fri Nov 30, 2018 3:36 pm
Contact:

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

Post by Gerkiz » Fri Jul 12, 2019 3:33 pm

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.
Attachments
log20190702.txt
(801.04 KiB) Downloaded 16 times
log20190701.txt
(15.45 KiB) Downloaded 17 times

grilledham
Inserter
Inserter
Posts: 21
Joined: Tue Sep 25, 2018 9:32 pm
Contact:

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

Post by grilledham » Fri Jul 12, 2019 3:57 pm

Oxyd wrote:
Fri Jul 12, 2019 2:10 pm
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
Inserter
Inserter
Posts: 21
Joined: Tue Sep 25, 2018 9:32 pm
Contact:

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

Post by grilledham » Fri Jul 12, 2019 4:25 pm

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
Attachments
factorio-current (11).log
(140.36 KiB) Downloaded 11 times
factorio-current20190712155805.log
(121.38 KiB) Downloaded 13 times

Oxyd
Factorio Staff
Factorio Staff
Posts: 1296
Joined: Thu May 07, 2015 8:42 am
Contact:

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

Post by Oxyd » Fri Jul 12, 2019 4:32 pm

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
Inserter
Inserter
Posts: 21
Joined: Tue Sep 25, 2018 9:32 pm
Contact:

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

Post by grilledham » Fri Jul 12, 2019 4:35 pm

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

Oxyd
Factorio Staff
Factorio Staff
Posts: 1296
Joined: Thu May 07, 2015 8:42 am
Contact:

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

Post by Oxyd » Fri Jul 12, 2019 4:47 pm

grilledham wrote:
Fri Jul 12, 2019 4:35 pm
The last two logs I uploaded use non-asynchronous or blocking saving. Is the problem likely fixed for blocking saving too?
Yes.

grilledham
Inserter
Inserter
Posts: 21
Joined: Tue Sep 25, 2018 9:32 pm
Contact:

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

Post by grilledham » Fri Jul 12, 2019 5:07 pm

OK, thanks. :D

mrvn
Smart Inserter
Smart Inserter
Posts: 3853
Joined: Mon Sep 05, 2016 9:10 am
Contact:

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

Post by mrvn » Mon Jul 15, 2019 10:12 am

Oxyd wrote:
Fri Jul 12, 2019 4:32 pm
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.

Post Reply

Return to “Resolved Problems and Bugs”

Who is online

Users browsing this forum: No registered users