Failure without controlling tty irrespective of -tt / -T
Alex Bligh
alex at alex.org.uk
Tue Sep 22 23:20:49 AEST 2015
On 22 Sep 2015, at 12:54, Alex Bligh <alex at alex.org.uk> wrote:
> I'm a bit at my wits end with this one.
>
> I'm seeing a problem where an automated script fails if it doesn't have a tty. Stripping it right back, the issue is that (open)ssh to a Windows build box VM succeeds if openssh has a controlling pty, and fails if it doesn't.
>
> IE:
>
> ssh -T host command succeeds
> ssh -tt host command succeeds
> nohup ssh -T host command fails
> nohup ssh -tt host command fails
>
> I'm running under 'env -i' to clear the environment off.
>
> I have verified the MS end is not actually running the command (as opposed to merely the output not showing) - for one it's 100 times quicker without nohup.
>
> I'm running:
> OpenSSH_6.6.1p1 Ubuntu-2ubuntu2, OpenSSL 1.0.1f 6 Jan 2014
I have a suspicion this might be an openssh client. strace shows the connection dies after receiving EBADF. However broken the ssh server is, I don't think openssh should be reading from an FD that returns EBADF.
Here's ssh launched with 'nohup'. Node the EBADF near the end (when it decides the connection is dead).
26857 1442926333.820491 write(2, "debug1: Entering interactive session.\r\n", 39) = 39
26857 1442926333.820580 rt_sigaction(SIGHUP, NULL, {SIG_IGN, [], 0}, 8) = 0
26857 1442926333.820658 rt_sigaction(SIGINT, NULL, {SIG_DFL, [], 0}, 8) = 0
26857 1442926333.820734 rt_sigaction(SIGINT, {SIG_IGN, [], SA_RESTORER, 0x7fac479f6d40}, NULL, 8) = 0
26857 1442926333.820804 rt_sigaction(SIGINT, NULL, {SIG_IGN, [], SA_RESTORER, 0x7fac479f6d40}, 8) = 0
26857 1442926333.820873 rt_sigaction(SIGINT, {0x7fac48e37950, [], SA_RESTORER, 0x7fac479f6d40}, NULL, 8) = 0
26857 1442926333.820942 rt_sigaction(SIGQUIT, NULL, {SIG_DFL, [], 0}, 8) = 0
26857 1442926333.821010 rt_sigaction(SIGQUIT, {SIG_IGN, [], SA_RESTORER, 0x7fac479f6d40}, NULL, 8) = 0
26857 1442926333.821078 rt_sigaction(SIGQUIT, NULL, {SIG_IGN, [], SA_RESTORER, 0x7fac479f6d40}, 8) = 0
26857 1442926333.821148 rt_sigaction(SIGQUIT, {0x7fac48e37950, [], SA_RESTORER, 0x7fac479f6d40}, NULL, 8) = 0
26857 1442926333.821216 rt_sigaction(SIGTERM, NULL, {SIG_DFL, [], 0}, 8) = 0
26857 1442926333.821285 rt_sigaction(SIGTERM, {SIG_IGN, [], SA_RESTORER, 0x7fac479f6d40}, NULL, 8) = 0
26857 1442926333.821353 rt_sigaction(SIGTERM, NULL, {SIG_IGN, [], SA_RESTORER, 0x7fac479f6d40}, 8) = 0
26857 1442926333.821421 rt_sigaction(SIGTERM, {0x7fac48e37950, [], SA_RESTORER, 0x7fac479f6d40}, NULL, 8) = 0
26857 1442926333.821489 rt_sigaction(SIGWINCH, NULL, {SIG_DFL, [], 0}, 8) = 0
26857 1442926333.821557 rt_sigaction(SIGWINCH, {0x7fac48e37bd0, [], SA_RESTORER, 0x7fac479f6d40}, NULL, 8) = 0
26857 1442926333.821642 select(7, [3], [3], NULL, NULL) = 1 (out [3])
26857 1442926333.821729 write(3, "\rN\0360KugC\333\245\311\30\rNPM\22)\265\223-\313\301U\363dk\241\312\354\274\303\314^(I\36z\360V\205\376\354TJ\364\v\227\217\227\tP\"\31O\233zy\17\372\337\226\3211", 64) = 64
26857 1442926333.821892 select(7, [3], [], NULL, NULL) = 1 (in [3])
26857 1442926333.822569 read(3, "zU\357\210T\356\241_y\263\v\301\217\351\355/{\206\264\2230\177\270\263r\255n\321\226[\33\25 \23\\\311\260\254\0e\261\327\3227\4\326\230\234", 8192) = 48
26857 1442926333.822683 write(2, "debug2: callback start\r\n", 24) = 24
26857 1442926333.822781 getsockopt(3, SOL_TCP, TCP_NODELAY, [0], [4]) = 0
26857 1442926333.822849 write(2, "debug2: fd 3 setting TCP_NODELAY\r\n", 34) = 34
26857 1442926333.822912 setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0
26857 1442926333.822972 getsockname(3, {sa_family=AF_INET, sin_port=htons(33222), sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
26857 1442926333.823039 write(2, "debug3: packet_set_tos: set IP_TOS 0x08\r\n", 41) = 41
26857 1442926333.823101 setsockopt(3, SOL_IP, IP_TOS, [8], 4) = 0
26857 1442926333.823163 write(2, "debug2: client_session2_setup: id 0\r\n", 37) = 37
26857 1442926333.823228 write(2, "debug1: Sending environment.\r\n", 30) = 30
26857 1442926333.823294 write(2, "debug1: Sending command: powershell /c echo hello\r\n", 51) = 51
26857 1442926333.823359 write(2, "debug2: channel 0: request exec confirm 1\r\n", 43) = 43
26857 1442926333.823445 write(2, "debug2: callback done\r\n", 23) = 23
26857 1442926333.823510 write(2, "debug2: channel 0: open confirm rwindow 131072 rmax 98304\r\n", 59) = 59
26857 1442926333.823582 select(7, [3 4], [3], NULL, NULL) = 2 (in [4], out [3])
26857 1442926333.823652 read(4, 0x7ffee032e970, 16384) = -1 EBADF (Bad file descriptor)
26857 1442926333.823725 write(2, "debug2: channel 0: read<=0 rfd 4 len -1\r\n", 41) = 41
26857 1442926333.823798 write(2, "debug2: channel 0: read failed\r\n", 32) = 32
26857 1442926333.823884 write(2, "debug2: channel 0: close_read\r\n", 31) = 31
26857 1442926333.823951 close(4) = 0
....
Here's ssh launched without 'nohup':
27010 1442926394.519659 write(2, "debug1: Entering interactive session.\r\n", 39) = 39
27010 1442926394.519886 rt_sigaction(SIGHUP, NULL, {SIG_DFL, [], 0}, 8) = 0
27010 1442926394.519961 rt_sigaction(SIGHUP, {SIG_IGN, [], SA_RESTORER, 0x7fcfdb1ccd40}, NULL, 8) = 0
27010 1442926394.520033 rt_sigaction(SIGHUP, NULL, {SIG_IGN, [], SA_RESTORER, 0x7fcfdb1ccd40}, 8) = 0
27010 1442926394.520114 rt_sigaction(SIGHUP, {0x7fcfdc60d950, [], SA_RESTORER, 0x7fcfdb1ccd40}, NULL, 8) = 0
27010 1442926394.520185 rt_sigaction(SIGINT, NULL, {SIG_DFL, [], 0}, 8) = 0
27010 1442926394.520257 rt_sigaction(SIGINT, {SIG_IGN, [], SA_RESTORER, 0x7fcfdb1ccd40}, NULL, 8) = 0
27010 1442926394.520327 rt_sigaction(SIGINT, NULL, {SIG_IGN, [], SA_RESTORER, 0x7fcfdb1ccd40}, 8) = 0
27010 1442926394.520398 rt_sigaction(SIGINT, {0x7fcfdc60d950, [], SA_RESTORER, 0x7fcfdb1ccd40}, NULL, 8) = 0
27010 1442926394.520469 rt_sigaction(SIGQUIT, NULL, {SIG_DFL, [], 0}, 8) = 0
27010 1442926394.520539 rt_sigaction(SIGQUIT, {SIG_IGN, [], SA_RESTORER, 0x7fcfdb1ccd40}, NULL, 8) = 0
27010 1442926394.520622 rt_sigaction(SIGQUIT, NULL, {SIG_IGN, [], SA_RESTORER, 0x7fcfdb1ccd40}, 8) = 0
27010 1442926394.520703 rt_sigaction(SIGQUIT, {0x7fcfdc60d950, [], SA_RESTORER, 0x7fcfdb1ccd40}, NULL, 8) = 0
27010 1442926394.520773 rt_sigaction(SIGTERM, NULL, {SIG_DFL, [], 0}, 8) = 0
27010 1442926394.520844 rt_sigaction(SIGTERM, {SIG_IGN, [], SA_RESTORER, 0x7fcfdb1ccd40}, NULL, 8) = 0
27010 1442926394.520914 rt_sigaction(SIGTERM, NULL, {SIG_IGN, [], SA_RESTORER, 0x7fcfdb1ccd40}, 8) = 0
27010 1442926394.520985 rt_sigaction(SIGTERM, {0x7fcfdc60d950, [], SA_RESTORER, 0x7fcfdb1ccd40}, NULL, 8) = 0
27010 1442926394.521056 rt_sigaction(SIGWINCH, NULL, {SIG_DFL, [], 0}, 8) = 0
27010 1442926394.521127 rt_sigaction(SIGWINCH, {0x7fcfdc60dbd0, [], SA_RESTORER, 0x7fcfdb1ccd40}, NULL, 8) = 0
27010 1442926394.521208 select(7, [3], [3], NULL, NULL) = 1 (out [3])
27010 1442926394.521295 write(3, "BG]\251\32b\217z\315\30d\17)\345\266\6\317\37\1\347j\224\10\350\321\347u{^\316\313\216\225\345\27\344\373\373q#mY\25\t\2553R]\371\372!\3756Uo92/j\325\4Z\200\346", 64) = 64
27010 1442926394.521611 select(7, [3], [], NULL, NULL) = 1 (in [3])
27010 1442926394.522086 read(3, "H\21\331!\370f\2373\34\306X1\376'\335X\"\326\277\25\321\332,\312\237N\341y\362\3721\236N\303\0169\313\2\30\2\216u\333TZ.\357\333", 8192) = 48
27010 1442926394.522178 write(2, "debug2: callback start\r\n", 24) = 24
27010 1442926394.522282 getsockopt(3, SOL_TCP, TCP_NODELAY, [0], [4]) = 0
27010 1442926394.522366 write(2, "debug2: fd 3 setting TCP_NODELAY\r\n", 34) = 34
27010 1442926394.522458 setsockopt(3, SOL_TCP, TCP_NODELAY, [1], 4) = 0
27010 1442926394.522534 getsockname(3, {sa_family=AF_INET, sin_port=htons(33230), sin_addr=inet_addr("127.0.0.1")}, [16]) = 0
27010 1442926394.522628 write(2, "debug3: packet_set_tos: set IP_TOS 0x08\r\n", 41) = 41
27010 1442926394.522719 setsockopt(3, SOL_IP, IP_TOS, [8], 4) = 0
27010 1442926394.522798 write(2, "debug2: client_session2_setup: id 0\r\n", 37) = 37
27010 1442926394.522892 write(2, "debug1: Sending environment.\r\n", 30) = 30
27010 1442926394.522985 write(2, "debug1: Sending command: powershell /c echo hello\r\n", 51) = 51
27010 1442926394.523085 write(2, "debug2: channel 0: request exec confirm 1\r\n", 43) = 43
27010 1442926394.523264 write(2, "debug2: callback done\r\n", 23) = 23
27010 1442926394.523391 write(2, "debug2: channel 0: open confirm rwindow 131072 rmax 98304\r\n", 59) = 59
27010 1442926394.523523 select(7, [3 4], [3], NULL, NULL) = 1 (out [3])
27010 1442926394.523616 write(3, "V0\300\\kSoD\353E\"+\344\7\251|\367s\232\22728\22\273\321\345\2H\321u\303Y\31A\237\201\271\326\21\367\360\350\242\353\266\210m\20r\2156\3447\316\5\24.\356\342p\17~D\371\2\245\245\205&T\20\3533F4_\202\273\36\347", 80) = 80
27010 1442926394.523733 select(7, [3 4], [], NULL, NULL) = 1 (in [3])
27010 1442926394.524474 read(3, "BV\351\356\351\353\340#{@\\6\341>\352)\342\241\307\270j\305\10J\322i`,\214\346a\275", 8192) = 32
27010 1442926394.524570 write(2, "debug2: channel_input_status_confirm: type 99 id 0\r\n", 52) = 52
27010 1442926394.524689 write(2, "debug2: exec request accepted on channel 0\r\n", 44) = 44
27010 1442926394.524785 select(7, [3 4], [], NULL, NULL) = 1 (in [3])
27010 1442926394.526720 read(3, "\262>\177ta\276\20\375\314\347\2441\240\254<|[\344\272\320\345X,\311\342\201q\241CV\"\314\305\2\314!|pq\235\341\22Y\"N\24Z\261", 8192) = 48
27010 1442926394.526816 write(2, "debug2: channel 0: rcvd adjust 0\r\n", 34) = 34
27010 1442926394.526906 select(7, [3 4], [], NULL, NULL) = 1 (in [3])
27010 1442926395.409546 read(3, "(\303\273\333H\217o\306\353\372\344(\340{\177\366<\323\237\300\223\251N\316E\0313PS$a\5\2334\372\226\324\33-QO\237\206C\3342(8", 8192) = 48
27010 1442926395.409610 select(7, [3 4], [5], NULL, NULL) = 1 (out [5])
27010 1442926395.409698 write(5, "hello\r\n", 7) = 7
27010 1442926395.409891 select(7, [3 4], [], NULL, NULL) = 1 (in [3])
27010 1442926395.440588 read(3, "\251d\352\315\351\26\276\316\246\321k\270\276\243\376=\343\273\372\205a\37R\34\271\304\203<\326\27\354%\35\322\366f\363\246\307\373\212-\32\327\214\277-\255\2612\304\254\256\337\2\216\35\230D2\35LN\365", 8192) = 64
27010 1442926395.440649 write(2, "debug1: client_input_channel_req: channel 0 rtype exit-status reply 0\r\n", 71) = 71
27010 1442926395.440805 select(7, [3 4], [], NULL, NULL) = 1 (in [3])
27010 1442926395.440935 read(3, "\324<,J\321\250\325H\376\322\230,\312\331\204\312&\266\230\221\240\3200\304\252\352lE\246\311\336]", 8192) = 32
27010 1442926395.441016 write(2, "debug2: channel 0: rcvd close\r\n", 31) = 31
27010 1442926395.441082 write(2, "debug2: channel 0: output open -> drain\r\n", 41) = 41
27010 1442926395.441144 write(2, "debug2: channel 0: close_read\r\n", 31) = 31
27010 1442926395.441234 close(4) = 0
27010 1442926395.441286 write(2, "debug2: channel 0: input open -> closed\r\n", 41) = 41
27010 1442926395.441382 write(2, "debug3: channel 0: will not send data after close\r\n", 51) = 51
27010 1442926395.441479 write(2, "debug2: channel 0: obuf empty\r\n", 31) = 31
27010 1442926395.441571 write(2, "debug2: channel 0: close_write\r\n", 32) = 32
27010 1442926395.441647 close(5) = 0
27010 1442926395.441708 write(2, "debug2: channel 0: output drain -> closed\r\n", 43) = 43
27010 1442926395.441796 write(2, "debug2: channel 0: almost dead\r\n", 32) = 32
....
The relevant lines seem to be:
26857 1442926333.818989 dup(0) = 4
26857 1442926333.819057 dup(1) = 5
26857 1442926333.819125 dup(2) = 6
...
26857 1442926333.823582 select(7, [3 4], [3], NULL, NULL) = 2 (in [4], out [3])
26857 1442926333.823652 read(4, 0x7ffee032e970, 16384) = -1 EBADF (Bad file descriptor)
...
27010 1442926395.441234 close(4) = 0
i.e. FD 4 is open (or the close would have errored), but returns EBADF.
I believe EBADF is only returned if the FD is closed, or not open for reading.
I think this happens because FD 0 gets set up like this by nohup:
28728 1442927535.524873 open("/dev/null", O_WRONLY) = 3
28728 1442927535.524947 dup2(3, 0) = 0
28728 1442927535.525008 close(3) = 0
Per line 125 of
https://fossies.org/dox/coreutils-8.24/nohup_8c_source.html
this is deliberate.
115 ignoring_input = isatty (STDIN_FILENO);
116 redirecting_stdout = isatty (STDOUT_FILENO);
117 stdout_is_closed = (!redirecting_stdout && errno == EBADF);
118 redirecting_stderr = isatty (STDERR_FILENO);
119
120 /* If standard input is a tty, replace it with /dev/null if possible.
121 Note that it is deliberately opened for *writing*,
122 to ensure any read evokes an error. */
123 if (ignoring_input)
124 {
125 if (fd_reopen (STDIN_FILENO, "/dev/null", O_WRONLY, 0) < 0)
126 error (exit_internal_failure, errno,
127 _("failed to render standard input unusable"));
128 if (!redirecting_stdout && !redirecting_stderr)
129 error (0, 0, _("ignoring input"));
130 }
131
132
('cron' and 'at' appear to do similarly)
And I have no idea why ssh should be reading from stdin when executing a command with -T.
--
Alex Bligh
More information about the openssh-unix-dev
mailing list