Delay sshd.socket startup on EC2 (sshd.socket race)?

[Nate Williams]

Short version.

We're using Terraform, and in our startup we do a number of things involving etcd, so we want to delay SSH connections to newly created instances until *AFTER* the nodes are fully integrated into the etcd cluster.  This used to work, but now the sshd socket is spun up and we connect to it before we get a chance to shut it down while we wait for the node to gain entry into the etcd cluster.

The question is, how do I completely disable remote SSH connections until some pre-determined set of events have occurred (timeout, happy etcd cluster, etc..).  Having SSH run for a bit, and then get disabled is a losing strategy as too many times the race is lost.

In earlier versions of CoreOS (pre-Ignition), we used user-data that looked something like this (we still use this setup, although it's not working).

-------------------- user-data --------------------

#cloud-config

...

write_files:

  - path: /opt/bin/waiter.sh

    content: |

      #!/bin/sh

      CMD="etcdctl cluster-health"

      # Try for at most 3 minutes (180s)

      MAX_TRIES=180

      until $CMD > /dev/null ; do

        if [ $MAX_TRIES -lt 0 ]; then

          break

        fi

        sleep 1

        MAX_TRIES=`expr $MAX_TRIES - 1`

      done

      [ $MAX_TRIES -gt 0 ]

      EXIT_VAL=$?

      if [ $EXIT_VAL ]; then

         echo "Cluster healthy"

      else

         echo "Cluster unhealthy"

      fi

      exit $EXIT_VAL

    owner: root:root

    permissions: '0755'

coreos:

..

  units:

    - name: sshd.socket

      command: stop

    - name: etcd2.service

      command: start

....

    - name: etcd2-waiter.service

      command: start

      content: |

        [Unit]

        Description=etcd2 waiter

        Wants=network-online.target

        Wants=etcd2.service

        After=etcd2.service

        After=network-online.target

        Before=sshd.socket

        [Service]

        ExecStart=/opt/bin/waiter.sh

        RemainAfterExit=true

        Type=oneshot

    - name: sshd.socket

      command: start

-------------------- user-data --------------------

The waiter script has an (arbitrary) wait of 180s, which seems to be about 3x longer than normal startup time for our CoeOS nodes, but allows for things to timeout in case everything is borked so we can login after-the-fact.

The default is for sshd.socket to be enabled, which is disabled as the first unit file command, then we startup etcd2, along with some other things that aren't germane to the discussion (mount disks, configure docker, etc..), and then finally, add the etcd2-waiter.service which has the critical piece of information 'Before=sshd.socket', and then restart sshd.socket which then delays listening unti the waiter script completes.

This worked great for us until recently (~4-6 weeks), when it appears that sshd.socket service runs prior to any of the cloud-config scripts being run.  Terraform races in and connects before the sshd.socket stop happens, and then everything blows up all over the place when we attempt to write to etcd (etcdctl set /foo/bar value).

Logs: CoreOS Version: Container Linux by CoreOS stable (1235.12.0)

Apr 13 05:14:05 etcd-0 coreos-cloudinit[960]: 2017/04/13 05:14:05 Calling unit command "stop" on "sshd.socket"'

Apr 13 05:14:05 etcd-0 systemd[1]: Closed sshd.socket.

Apr 13 05:14:06 etcd-0 sshd[1019]: Accepted publickey for core from 10.0.0.6 port 61260 ssh2: RSA ... #This is Terraform logging in

Apr 13 05:14:06 etcd-0 coreos-cloudinit[960]: 2017/04/13 05:14:06 Calling unit command "start" on "etcd2-waiter.service"'

...

Apr 13 05:14:19 etcd-0 coreos-cloudinit[960]: 2017/04/13 05:14:19 Calling unit command "start" on "sshd.socket"'

Terraform lost (won?) the race, and all attempts to disable sshd.socket *completely* have failed, as it's starting before (and/or it's actually never stopping) I get a chance to shut it down.  Sometimes things work, but about 25% of the time (and more often at night when debugging when AWS is less busy) the race is lost.

I've tried using drop-ins, replacing the sshd.socket service file using the data from the CoreOS page, and all sorts of variations on settings that used to work in the past.  Note, I have NOT tried Ignition, simply because I can't figure out an easy way to dynamically create configuration files using Ignition using Terraform, and having a separate 'ct' binary just to create configuration files seems to be taking a step backwards.  Certainly that's the case for our usage of CoreOS and Terraform.

On a whim, I updated to the latest AMI hoping it would make a difference, but alas, no luck.

CoreOS Version: Container Linux by CoreOS stable (1298.7.0)

Apr 13 06:08:34 etcd-0 coreos-cloudinit[897]: 2017/04/13 06:08:34 Calling unit command "stop" on "sshd.socket"

Apr 13 06:08:34 etcd-0 systemd[1]: Reached target Multi-User System.

Apr 13 06:08:34 etcd-0 systemd-networkd[824]: eth0: Gained IPv6LL

Apr 13 06:08:34 etcd-0 systemd[1]: Started Garbage Collection for rkt.

Apr 13 06:08:34 etcd-0 systemd[1]: Closed sshd.socket.

Apr 13 06:08:34 etcd-0 coreos-cloudinit[897]: 2017/04/13 06:08:34 Result of "stop" on "sshd.socket": done

Apr 13 06:08:34 etcd-0 coreos-cloudinit[897]: 2017/04/13 06:08:34 Calling unit command "start" on "format-ephemeral.service"

Apr 13 06:08:35 etcd-0 sshd[893]: Accepted publickey for core from 10.0.0.6 port 62476 ssh2: RSA ....

...

Apr 13 06:13:06 etcd-0 coreos-cloudinit[897]: 2017/04/13 06:13:06 Calling unit command "start" on "etcd2-waiter.service"

Apr 13 06:13:07 etcd-0 waiter.sh[1045]: Cluster healthy

Apr 13 06:13:07 etcd-0 coreos-cloudinit[897]: 2017/04/13 06:13:07 Calling unit command "start" on "sshd.socket"

Same issue. The qu

Thanks for any insight that you can provide.

Nate

[David Michael]

On Wed, Apr 12, 2017 at 11:31 PM, Nate Williams <nate...@gmail.com> wrote:
> We're using Terraform, and in our startup we do a number of things involving
> etcd, so we want to delay SSH connections to newly created instances until
> *AFTER* the nodes are fully integrated into the etcd cluster. This used to
> work, but now the sshd socket is spun up and we connect to it before we get
> a chance to shut it down while we wait for the node to gain entry into the
> etcd cluster.

Such races are inevitable with cloud-config, especially with socket
units which are ordered before basic.target. I tried this Ignition
file, and it seems to work for me. (The "contents" string is one
line, if it gets wrapped in the e-mail.)

{
"ignition": { "version": "2.0.0" },
"systemd": {
"units": [
{
"name": "waiter.service",
"enable": true,
"contents": "[Unit]\nAfter=etcd.service etcd2.service
etcd-member.service\n\n[Service]\nType=oneshot\nTimeoutStartSec=180\nExecStart=/usr/bin/sh
-c 'until etcdctl cluster-health ; do sleep 1 ;
done'\n\n[Install]\nWantedBy=multi-user.target"
},
{
"name": "sshd@.service",
"dropins": [{
"name": "waiter.conf",
"contents": "[Unit]\nAfter=waiter.service"
}]
},
{
"name": "etcd-member.service",
"enable": true
}
]

}
}

> I've tried using drop-ins, replacing the sshd.socket service file using the
> data from the CoreOS page, and all sorts of variations on settings that used
> to work in the past. Note, I have NOT tried Ignition, simply because I
> can't figure out an easy way to dynamically create configuration files using
> Ignition using Terraform, and having a separate 'ct' binary just to create
> configuration files seems to be taking a step backwards. Certainly that's
> the case for our usage of CoreOS and Terraform.

What exactly works with cloud-config and not Ignition? Ignition can
write configuration files using "storage" (
https://coreos.com/ignition/docs/latest/configuration-v2_0.html ), or
if they need to be dynamically generated, it can just use a
Type=oneshot service with ConditionFirstBoot=yes .

Thanks.

David

[Alex Crawford]

To build on David's suggestion, Container Linux Configs can be used to
nicely express these configs. These can be fed to CT [1] to generate an
Ignition config or if using Matchbox, this will happen transparently. An
equivelent config would look as follows:

systemd:
units:
- name: waiter.service
contents: |
[Unit]
After=etcd.service etcd2.service etcd-member.service

[Service]
Type=oneshot
TimeoutStartSec=180

ExecStart=/usr/bin/sh -c 'until etcdctl cluster-health ; do sleep 1 ; done'

[Install]
WantedBy=multi-user.target

- name: sshd@.service
dropins:
- name: waiter.conf
contents: |
[Unit]
After=waiter.service

- name: etcd-member.service
enable: true

If I understand correctly though, etcd won't mark itself as started
until it has quorum, so it should be sufficient to just depend on
etcd-member.service.

systemd:
units:
- name: sshd@.service
dropins:
- name: wait-on-etcd.conf
contents: |
[Unit]
After=etcd-member.service

- name: etcd-member.service

enable: true


> > I've tried using drop-ins, replacing the sshd.socket service file using the
> > data from the CoreOS page, and all sorts of variations on settings that used
> > to work in the past. Note, I have NOT tried Ignition, simply because I
> > can't figure out an easy way to dynamically create configuration files using
> > Ignition using Terraform, and having a separate 'ct' binary just to create
> > configuration files seems to be taking a step backwards. Certainly that's
> > the case for our usage of CoreOS and Terraform.
>
> What exactly works with cloud-config and not Ignition? Ignition can
> write configuration files using "storage" (
> https://coreos.com/ignition/docs/latest/configuration-v2_0.html ), or
> if they need to be dynamically generated, it can just use a
> Type=oneshot service with ConditionFirstBoot=yes .

I am curious to learn more about your use-case. Why do you want to
prevent logins until etcd is up and running?

-Alex

[David Michael]

Empirical evidence contradicts this. If that is the intended
behavior, then there is a bug.

> systemd:
> units:
> - name: sshd@.service
> dropins:
> - name: wait-on-etcd.conf
> contents: |
> [Unit]
> After=etcd-member.service
>
> - name: etcd-member.service
> enable: true
>
>
>> > I've tried using drop-ins, replacing the sshd.socket service file using the
>> > data from the CoreOS page, and all sorts of variations on settings that used
>> > to work in the past. Note, I have NOT tried Ignition, simply because I
>> > can't figure out an easy way to dynamically create configuration files using
>> > Ignition using Terraform, and having a separate 'ct' binary just to create
>> > configuration files seems to be taking a step backwards. Certainly that's
>> > the case for our usage of CoreOS and Terraform.
>>
>> What exactly works with cloud-config and not Ignition? Ignition can
>> write configuration files using "storage" (
>> https://coreos.com/ignition/docs/latest/configuration-v2_0.html ), or
>> if they need to be dynamically generated, it can just use a
>> Type=oneshot service with ConditionFirstBoot=yes .
>
> I am curious to learn more about your use-case. Why do you want to
> prevent logins until etcd is up and running?

We have to do the same thing in kola tests, or they randomly fail when
SSH connections races against cluster health. Any automated system
connecting over SSH to interact with something backed by etcd is going
to have the same problem.

Thanks.

David

[Nate Williams]

[ Thanks both David and Alex for the help ]

> On Thu, Apr 13, 2017 at 12:52 PM, Alex Crawford
> <alex.c...@coreos.com> wrote:
>> On 04/13, David Michael wrote:
>>> On Wed, Apr 12, 2017 at 11:31 PM, Nate Williams <nate...@gmail.com> wrote:

>>>> [ SSH startup race waiting for etcd using cloud-config ]

>>> Such races are inevitable with cloud-config, especially with socket
>>> units which are ordered before basic.target. I tried this Ignition
>>> file, and it seems to work for me. (The "contents" string is one
>>> line, if it gets wrapped in the e-mail.)

[ SNIP ]

Thanks. I spent many hours this weekend coaxing TF to generate simple
Ignition files, and was able to get an identical configuration file as
removed above. The node works great at first bootup, but the box
refuses to allow SSH connections after reboot. :(

>>>> Note, I have NOT tried Ignition, simply because I can't figure out
>>>> an easy way to dynamically create configuration files using
>>>> Ignition using Terraform, and having a separate 'ct' binary just to
>>>> create configuration files seems to be taking a step backwards.
>>>> Certainly that's the case for our usage of CoreOS and Terraform.
>>>
>>> What exactly works with cloud-config and not Ignition?

The issue is not cloud-config vs. Ignition, it's requiring another
binary (ct) to be run to generate the config's dynamically, which
doesn't play well in Terraform. TF does have a way to generate Ignition
configuration files, but it's > 9 months out-of-date, and given recent
ignition configuration changes (configuring and etcd/locksmith), so
creating configuration is non-trivial, to say the least.

>>> Ignition can write configuration files using "storage" (
>>> https://coreos.com/ignition/docs/latest/configuration-v2_0.html ),
>>> or if they need to be dynamically generated, it can just use a
>>> Type=oneshot service with ConditionFirstBoot=yes .

I'll have to research this more. I don't see much documentation on
ConditionFirstBoot anywhere, except for some articles that imply it's
usage.

>> I am curious to learn more about your use-case. Why do you want to
>> prevent logins until etcd is up and running?
>
> We have to do the same thing in kola tests, or they randomly fail when
> SSH connections races against cluster health. Any automated system
> connecting over SSH to interact with something backed by etcd is going
> to have the same problem.

To summarize, I no longer have SSH races at first boot, but I can no
longer connect to instance after it's rebooted, so I'm still stuck. :(

Thanks for your help, and Happy Easter!



Nate

[Alex Crawford]

On 04/16, Nate Williams wrote:
> Thanks. I spent many hours this weekend coaxing TF to generate simple
> Ignition files, and was able to get an identical configuration file as
> removed above. The node works great at first bootup, but the box
> refuses to allow SSH connections after reboot. :(

Uh oh. Let's dig into this.

> The issue is not cloud-config vs. Ignition, it's requiring another
> binary (ct) to be run to generate the config's dynamically, which
> doesn't play well in Terraform. TF does have a way to generate Ignition
> configuration files, but it's > 9 months out-of-date, and given recent
> ignition configuration changes (configuring and etcd/locksmith), so
> creating configuration is non-trivial, to say the least.

Ah, the new features you are referring to are not a part of Ignition,
but actually a part of Container Linux Configs (which are transpiled
into Ignition Configs). We are working on a Container Linux Config
provider for Terraform which will allow you to take advantage of these
features.

> To summarize, I no longer have SSH races at first boot, but I can no
> longer connect to instance after it's rebooted, so I'm still stuck. :(

Do you have access to the serial logs from the machine? Can you show the
output of `systectl cat sshd@'? It's very odd that it works on the first
boot but not subsequent boots. Ignition is designed to make sure that
the first boot is no longer a special case.

-Alex

[Nate Williams]

Alex Crawford writes:
> On 04/16, Nate Williams wrote:
> > Thanks. I spent many hours this weekend coaxing TF to generate simple
> > Ignition files, and was able to get an identical configuration file as
> > removed above. The node works great at first bootup, but the box
> > refuses to allow SSH connections after reboot. :(
>
> Uh oh. Let's dig into this.
>
> > The issue is not cloud-config vs. Ignition, it's requiring another
> > binary (ct) to be run to generate the config's dynamically, which
> > doesn't play well in Terraform. TF does have a way to generate Ignition
> > configuration files, but it's > 9 months out-of-date, and given recent
> > ignition configuration changes (configuring and etcd/locksmith), so
> > creating configuration is non-trivial, to say the least.
>
> Ah, the new features you are referring to are not a part of Ignition,
> but actually a part of Container Linux Configs (which are transpiled
> into Ignition Configs). We are working on a Container Linux Config
> provider for Terraform which will allow you to take advantage of these
> features.

Whoo hoo!

> > To summarize, I no longer have SSH races at first boot, but I can no
> > longer connect to instance after it's rebooted, so I'm still stuck. :(
>
> Do you have access to the serial logs from the machine?

I just found out I can get access to the serial logs on AWS. Yay!

TL;DR
-----
[[0;1;31mFAILED[0m] Failed to start etcd (System Application Container).
See 'systemctl status etcd-member.service' for details.
-----
(Edited logs attached below)

I believe it's complaining about a dependency loop, since that's
happened a bunch of times as well, but since I don't have SSH access
(SSH is working, but it won't allow logins using my PEM), I can't do any
more debugging.

At this point on this particular server, I have SSH working, but the PEM
keys are not working properly so I can't login(??). Other times I have
no SSH, other times etcd is not running. It's very inconsistent.

> Can you show the output of `systectl cat sshd@'? It's very odd that it
> works on the first boot but not subsequent boots. Ignition is designed
> to make sure that the first boot is no longer a special case.

Since I can't login, I can't run any commands like 'systemctl cat
sshd@', but I may be able to do that by rebuilding the box and not
rebooting it.

Here you go:
------------------ cut here ------------------
$ systemctl cat sshd@
# /usr/lib/systemd/system/sshd@.service
[Unit]
Description=OpenSSH per-connection server daemon
After=syslog.target auditd.service

[Service]
ExecStart=-/usr/sbin/sshd -i -e
StandardInput=socket
StandardError=syslog

# /usr/lib64/systemd/system/sshd@.service.d/sshd-keygen.conf
[Unit]
Wants=sshd-keygen.service
After=sshd-keygen.service
# /etc/systemd/system/sshd@.service.d/waiter.conf
[Unit]
After=waiter.service
------------------ cut here ------------------

Thanks for your help!




Nate

------------------------- serial logs -------------------------
[ 0.000000] Linux version 4.9.16-coreos-r1 (jenkins@localhost) (gcc
version 4.9.3 (Gentoo Hardened 4.9.3 p1.5, pie-0.6.4) ) #1 SMP Fri Mar
31 02:07:42 UTC 2017
[ 0.000000] Command line: BOOT_IMAGE=/coreos/vmlinuz-a
mount.usr=/dev/mapper/usr
verity.usr=PARTUUID=7130c94a-213a-4e5a-8e26-6cce9662f132 rootflags=rw
mount.usrflags=ro consoleblank=0 root=LABEL=ROOT console=ttyS0,115200n8
coreos.first_boot=1
coreos.randomize_disk_guid=00000000-0000-0000-0000-000000000001
coreos.oem.id=ec2 modprobe.blacklist=xen_fbfront net.ifnames=0
verity.usrhash=bdba6be8dc5acdf23b3ad079600f3ae57c7e30a6994e9431357eb80cee98609a
...
Welcome to [0;34mdracut-044 (Initramfs)[0m!
...
[ 4.661367] systemd[1]: Starting Ignition (files)... Starting
Ignition (files)...

[ 4.670481] ignition[427]: Ignition v0.12.1
[ 4.674338] ignition[[0;32m OK [0m] Started Ignition (files).
[427]: files: op(1): [started] processing unit
"coreos-metadata-sshkeys@.service"Starting Reload Configuration from the
Real Root...
[[0;32m OK [0m] Reached target ignition.target.

[ 4.699320] ignition[427]: files: op(1): [finished] processing unit
"coreos-metadata-sshkeys@.service"
[ 4.720300] systemd[1]: Started Ignition (files).
[ 4.731987] ignition[427]: files: op(2): [started] enabling unit
"coreos-metadata-sshkeys@.service"
[ 4.748717] systemd[1]: Starting Reload Configuration from the Real
Root...
[ 4.760672] ignition[427]: files: op(2): [finished] enabling unit
"coreos-metadata-sshkeys@.service"
[ 4.780003] systemd[1]: Reached target ignition.target.
[ 4.788329] ignition[427]: files: op(3): [started] processing unit
"waiter.service"
[ 4.803233] systemd[1]: Reloading.
[ 4.815863] ignition[427]: files: op(3): op(4): [started] writing
unit "waiter.service" at "etc/systemd/system/waiter.service"
[ 4.836170] ignition[427]: files: op(3): op(4): [finished] writing
unit "waiter.service" at "etc/systemd/system/waiter.service"
[[0;32m OK [0m] Started Reload Configuration from the Real Root.[
4.859880] systemd[1]: Started Reload Configuration from the Real Root.
[ 4.864673] ignition[427]: files: op(3): [finished] processing unit
"waiter.service"
[ 4.873021]
[[0;32m OK [0m] Reached target Initrd File Systems.
[[0;32m OK [0m] Reached target Initrd Default Target.
Starting dracut pre-pivot and cleanup hook...
[[0;32m OK [0m] Started dracut pre-pivot and cleanup hook.
Starting Cleaning Up and Shutting Down Daemons...
ignition[427]: files: op(5): [started] enabling unit
"waiter.service"[[0;32m OK [0m] Stopped Cleaning Up and Shutting Down
Daemons.

[[0;32m OK [0m[ 4.954111] systemd[1]: Reached target Initrd File
Systems.
[ 4.960598] ignition[427]: files: op(5): [finished] enabling unit
"waiter.service"] Stopped dracut pre-pivot and cleanup hook.

[ 4.976630] systemd[1]: Reached target Initrd Default
Target.
[ 4.987463] ignition[427]: files: op(6): [started] processing unit
"sshd@.service"Stopping Network Name Resolution...
[[0;32m OK [0m] Stopped target ignition.target.
[[0;32m OK [0m] Stopped dracut pre-mount hook.
[[0;32m OK [0m] Stopped target Timers.
[[0;32m OK [0m] Stopped target Remote File Systems.
[[0;32m OK [0m] Stopped target Remote File Systems (Pre).
[[0;32m OK [0m] Stopped target Initrd Default Target.
[[0;32m OK [0m] Stopped dracut initqueue hook.
[[0;32m OK [0m] Stopped target Basic System.
[[0;32m OK [0m] Stopped target Paths.
[[0;32m OK [0m] Stopped Dispatch Password Requests to Console
Directory Watch.
[[0;32m OK [0m] Stopped target System Initialization.
[[0;32m OK [0m] Stopped udev Coldplug all Devices.
[[0;32m OK [0m] Stopped dracut pre-trigger hook.
[[0;32m OK [0m] Stopped target Swap.
[[0;32m OK [0m] Stopped target Encrypted Volumes.
[[0;32m OK [0m] Stopped target Slices.
[[0;32m OK [0m] Stopped target Sockets.
[[0;32m OK [0m] Stopped target Local File Systems.
[[0;32m OK [0m] Stopped target Local File Systems (Pre).
[[0;32m OK [0m] Stopped Network Name Resolution.
[[0;32m OK [0m] Stopped target Network.
Stopping Network Service...
[[0;32m OK [0m] Stopped Network Service.
[ 5.103805]
Stopping udev Kernel Device Manager...systemd[1]: Starting
dracut pre-pivot and cleanup hook...
[ 5.114216] ignition[427]: files: op(6): op(7): [started] writing
drop-in "waiter.conf" at
"etc/systemd/system/sshd@.service.d/waiter.conf"
[[0;32m OK [0m] Stopped Apply Kernel Variables.
[[0;32m OK [0m] Closed Network Service Netlink Socket.
[[0;32m OK [0m] Stopped udev Kernel Device Manager.
[[0;32m OK [0m] Stopped dracut pre-udev hook.
[ 5.141620] systemd[1]: Started dracut pre-pivot and cleanup hook.
[[0;32m OK [0m] Stopped dracut cmdline hook.
[ 5.153768] ignition[427]: files: op(6): op(7): [finished] writing
drop-in "waiter.conf" at
"etc/systemd/system/sshd@.service.d/waiter.conf"
[[0;32m OK [0m] Stopped Create Static Device Nodes in /dev.
[[0;32m OK [0m] Stopped Create list of required sta...ce nodes for the
current kernel.
[ 5.193120] systemd[1]: Starting Cleaning Up and Shutting Down
Daemons...
[ 5.210286] ignition[427]: files: op(6): [finished] processing unit
"sshd@.service"
[ 5.226612] systemd[1]: Stopped Cleaning Up and Shutting Down
Daemons.
[ 5.232403] ignition[427]: files: op(8): [started] enabling unit
"sshd@.service"
[ 5.237776] systemd[1]: Stopped dracut pre-pivot and cleanup hook.
[ 5.242417] ignition[427]: files: op(8): [finished] enabling unit
"sshd@.service"
[ 5.260429] systemd[1]: Stopping Network Name Resolution...
[ 5.272399] ignition[427]: files: op(9): [started] processing unit
"etcd-member.service"
[ 5.278414] systemd[1]: Stopped target ignition.target.
[ 5.282728] ignition[427]: files: op(9): [finished] processing unit
"etcd-member.service"
[ 5.288112] systemd[1]: Stopped dracut pre-mount hook.
[ 5.292092] ignition[427]: files: op(a): [started] enabling unit
"etcd-member.service"
[ 5.297375] systemd[1]: Stopped target Timers.
[ 5.301425] ignition[427]: files: op(a): [finished] enabling unit
"etcd-member.service"
[ 5.307425] systemd[1]: Stopped target Remote File Systems.
....
Welcome to [38;5;75mContainer Linux by CoreOS 1298.7.0 (Ladybug)[0m!
...
[[0;32m OK [0m] Started Update is Completed.
[[0;32m OK [0m] Reached target System Initialization.
[[0;32m OK [0m] Listening on OpenSSH Server Socket.
Starting rkt metadata service socket.
[[0;32m OK [0m] Started Periodic Garbage Collection for rkt.
[[0;32m OK [0m] Started Daily Cleanup of Temporary Directories.
[[0;32m OK [0m] Started Watch for a cloud-config at
/var/lib/coreos-install/user_data.
[[0;32m OK [0m] Started Watch for update engine configuration changes.
[[0;32m OK [0m] Reached target Paths.
Starting Docker Socket for the API.
[[0;32m OK [0m] Listening on D-Bus System Message Bus Socket.
[[0;32m OK [0m] Started Daily Log Rotation.
[[0;32m OK [0m] Reached target Timers.
[[0;32m OK [0m] Listening on rkt metadata service socket.
[[0;32m OK [0m] Listening on Docker Socket for the API.
[[0;32m OK [0m] Reached target Sockets.
[[0;32m OK [0m] Reached target Basic System.
Starting Generate sshd host keys...
Starting etcd (System Application Container)...
Starting Garbage Collection for rkt...
Starting Install an ssh key from /proc/cmdline...
[[0;32m OK [0m] Started Cluster reboot manager.
Starting Generate /run/coreos/motd...
Starting Extend Filesystems...
Starting CoreOS Metadata Agent (SSH Keys)...
Starting Update Engine...
Starting Login Service...
[[0;32m OK [0m] Started D-Bus System Message Bus.
[ 14.148336] extend-filesystems[829]: resize2fs 1.42.13 (17-May-2015)
[ 14.156400] EXT4-fs (xvda9): resizing filesystem from 553472 to
1489915 blocks
[ 14.215232] EXT4-fs (xvda9): resized filesystem to 1489915
Starting Load cloud-config from
/usr/share/oem/cloud-config.yml...
Starting Network Service...
[[0;32m OK [0m] Started Install an ssh key from /proc/cmdline.
[[0;32m OK [0m] Started Generate /run/coreos/motd.
[[0;32m OK [0m] Started Login Service.
[[0;32m OK [0m] Started Update Engine.
[ 14.369113] [[0;32m OK [0m] Started Network Service.
[[0;32m OK [0m] Reached target Network.
Starting Network Name Resolution...
[[0;32m OK [0m] Started Extend Filesystems.
extend-filesystems[829]: Filesystem at /dev/xvda9 is mounted on /;
on-line resizing required Starting Hostname Service...

[ 14.434704] extend-filesystems[829]: old_desc_blocks = 1,
new_desc_blocks = 1
[ 14.449765] [[0;32m OK [0m] Started Hostname Service.
Starting Authorization Manager...
[[0;32m OK [0m] Started Network Name Resolution.
extend-filesystems[829]: The filesystem on /dev/xvda9 is now 1489915
(4k) blocks long.
Starting Cloudinit from EC2-style metadata...
[[0;32m OK [0m] Started Cloudinit from EC2-style metadata.
[[0;32m OK [0m] Started Load cloud-config from
/usr/share/oem/cloud-config.yml.
[[0;32m OK [0m] Reached target Load system-provided cloud configs.
[[0;32m OK [0m] Reached target Load user-provided cloud configs.
[[0;32m OK [0m] Started Authorization Manager.
[[0;1;31mFAILED[0m] Failed to start etcd (System Application Container).
See 'systemctl status etcd-member.service' for details.
[[0;32m OK [0m] Started Garbage Collection for rkt.
Starting waiter.service...
[[0;32m OK [0m] Started Generate sshd host keys.
Starting Generate /run/issue...
[[0;32m OK [0m] Started Generate /run/issue.
Starting Permit User Sessions...
[[0;32m OK [0m] Started CoreOS Metadata Agent (SSH Keys).
[[0;32m OK [0m] Started Permit User Sessions.
[[0;32m OK [0m] Started Serial Getty on ttyS0.
[[0;32m OK [0m] Started Getty on tty1.
[[0;32m OK [0m] Reached target Login Prompts.
[[0;32m OK [0m] Created slice system-sshd.slice.

SSH host key: SHA256:XXXX (ASDFADSF)
SSH host key: SHA256:YYYY (DSA)
SSH host key: SHA256:WWW (RSA)(
SSH host key: SHA256:ZZZ (ECDSA)
eth0: 10.0.254.5 fe80::ce:9aff:fe86:873d

ip-10-0-254-5 login:
------------------------- serial logs -------------------------

[Alex Crawford]

On 04/17, Nate Williams wrote:
> I just found out I can get access to the serial logs on AWS. Yay!
>
> TL;DR
> -----
> [[0;1;31mFAILED[0m] Failed to start etcd (System Application Container).
> See 'systemctl status etcd-member.service' for details.
> -----
> (Edited logs attached below)
>
> I believe it's complaining about a dependency loop, since that's
> happened a bunch of times as well, but since I don't have SSH access
> (SSH is working, but it won't allow logins using my PEM), I can't do any
> more debugging.

If it were a dependency loop, you would see that very explicitly in the
logs (systemd will mention it is breaking the loop). I didn't see
anything in the logs you attached.

> At this point on this particular server, I have SSH working, but the PEM
> keys are not working properly so I can't login(??). Other times I have
> no SSH, other times etcd is not running. It's very inconsistent.

Is it actually starting the key exchange or is it just systemd accepting
the incoming connection (though I would think systemd would close the
connection if it failed to start the process). You can check this by
throwing `-vvv` on to your ssh invocation.

This sort of fragile behavior would definitely be concerning. Most times
I want to get into a machine is when something has gone wrong (like
etcd) and if that's blocked for any reason it's going to make my life
very tricky. What was the ultimate reason you wanted this behavior?
There might be a better way to solve the problem.

-Alex

[Nate Williams]

> On 04/17, Nate Williams wrote:
> > I just found out I can get access to the serial logs on AWS. Yay!
> >
> > TL;DR
> > -----
> > [[0;1;31mFAILED[0m] Failed to start etcd (System Application Container).
> > See 'systemctl status etcd-member.service' for details.
> > -----
> > (Edited logs attached below)
> >
> > I believe it's complaining about a dependency loop, since that's
> > happened a bunch of times as well, but since I don't have SSH access
> > (SSH is working, but it won't allow logins using my PEM), I can't do any
> > more debugging.
>
> If it were a dependency loop, you would see that very explicitly in the
> logs (systemd will mention it is breaking the loop). I didn't see
> anything in the logs you attached.

I saw that in logs from yesterday for the same service. I have no idea
why it failed earlier since the boot logs didn't provide enough
information.

> > At this point on this particular server, I have SSH working, but the PEM
> > keys are not working properly so I can't login(??). Other times I have
> > no SSH, other times etcd is not running. It's very inconsistent.
>
> Is it actually starting the key exchange or is it just systemd accepting
> the incoming connection (though I would think systemd would close the
> connection if it failed to start the process). You can check this by
> throwing `-vvv` on to your ssh invocation.

It (was) accepting the connectino, but was not allowing SSH key logins,
and forcing me to provide a password. I don't have any accounts with
passwords on this box.

But, this is the first time I've had it fail with SSH allowing
connections, but not configured properly. Like I said, I'm getting
very inconsistent behavior.

> This sort of fragile behavior would definitely be concerning. Most times
> I want to get into a machine is when something has gone wrong (like
> etcd) and if that's blocked for any reason it's going to make my life
> very tricky. What was the ultimate reason you wanted this behavior?

The very first thing I do once a new box is created is

etcdctl set /cluster/${role}/${name} ${COREOS_EC2_IPV4_LOCAL}

where ${role} and ${name} are dynamically set by Terraform

We use this information to automate a number of post-spinup
configuration steps.

If the cluster isn't healthy, this step fails.


Nate

[Alex Crawford]

On 04/17, Nate Williams wrote:
> It (was) accepting the connectino, but was not allowing SSH key logins,
> and forcing me to provide a password. I don't have any accounts with
> passwords on this box.
>
> But, this is the first time I've had it fail with SSH allowing
> connections, but not configured properly. Like I said, I'm getting
> very inconsistent behavior.

Hmm, if you are setting the passwords and SSH keys via Ignition, that
should always work. If you are seeing inconsistent behavior, then there
is probably something else trying to help configure user accounts.

> > This sort of fragile behavior would definitely be concerning. Most times
> > I want to get into a machine is when something has gone wrong (like
> > etcd) and if that's blocked for any reason it's going to make my life
> > very tricky. What was the ultimate reason you wanted this behavior?
>
> The very first thing I do once a new box is created is
>
> etcdctl set /cluster/${role}/${name} ${COREOS_EC2_IPV4_LOCAL}
>
> where ${role} and ${name} are dynamically set by Terraform
>
> We use this information to automate a number of post-spinup
> configuration steps.
>
> If the cluster isn't healthy, this step fails.

I presume the purpose of this is to prevent other automated systems from
SSHing in if there is a problem. Have you considered creating dedicated
accounts for these services so that you can block their access, yet
still leave a way in for manual debugging? Might be overkill for what
you are trying to do.

-Alex

[Nate Williams]

Alex Crawford writes:
> On 04/17, Nate Williams wrote:
> > It (was) accepting the connectino, but was not allowing SSH key logins,
> > and forcing me to provide a password. I don't have any accounts with
> > passwords on this box.
> >
> > But, this is the first time I've had it fail with SSH allowing
> > connections, but not configured properly. Like I said, I'm getting
> > very inconsistent behavior.
>
> Hmm, if you are setting the passwords and SSH keys via Ignition, that
> should always work.

*shrug*

> If you are seeing inconsistent behavior, then there
> is probably something else trying to help configure user accounts.

The PEM is being set by Amazon when it spins up the instance.

> > > This sort of fragile behavior would definitely be concerning. Most times
> > > I want to get into a machine is when something has gone wrong (like
> > > etcd) and if that's blocked for any reason it's going to make my life
> > > very tricky. What was the ultimate reason you wanted this behavior?
> >
> > The very first thing I do once a new box is created is
> >
> > etcdctl set /cluster/${role}/${name} ${COREOS_EC2_IPV4_LOCAL}
> >
> > where ${role} and ${name} are dynamically set by Terraform
> >
> > We use this information to automate a number of post-spinup
> > configuration steps.
> >
> > If the cluster isn't healthy, this step fails.
>
> I presume the purpose of this is to prevent other automated systems from
> SSHing in if there is a problem.

It's to prevent them from logging in until the box is fully established
into the cluster.

> Have you considered creating dedicated accounts for these services so
> that you can block their access, yet still leave a way in for manual
> debugging? Might be overkill for what you are trying to do.

The account is only used at node startup, and I'd have the same issues
disabling them until etcd is fully configured as I do know.


Nate

[Alex Crawford]

On 04/17, Nate Williams wrote:
> Alex Crawford writes:
> > On 04/17, Nate Williams wrote:
> > > It (was) accepting the connectino, but was not allowing SSH key logins,
> > > and forcing me to provide a password. I don't have any accounts with
> > > passwords on this box.
> > >
> > > But, this is the first time I've had it fail with SSH allowing
> > > connections, but not configured properly. Like I said, I'm getting
> > > very inconsistent behavior.
> >
> > Hmm, if you are setting the passwords and SSH keys via Ignition, that
> > should always work.
>
> *shrug*

Were you able to determine why etcd failed to start?

-Alex

[Alex Crawford]

On 04/19, Nathan Williams wrote:
> I'm at a standstill, and am looking at adding crappy code to do something
> like 'sleep 90' at the start of my initial node spinup to avoid the SSH
> race, since Ignition is giving us no-end of problems. I don't know what
> the problem, but if I use the exact same configuration and create a node
> 10x, it will work fine 5 out of the ten times, and it will fail to allow
> logins 5 of the times. And, even if it spins up correctly the first 5
> instances, it will eventually fail to allow logins if I reboot it enough
> times. I've got 40+ hours into trying to make this work, and I'm no
> further along now than I was last week.
>
> This smells very much like a race in how Ignition does it's thing, but b/c
> the logs aren't very helpful, and the only access I have to the EC2
> instance is via SSH, it makes it very difficult to debug the issue. So,
> we're going to give up on Ignition b/c it's just too fragile, and hope it
> gets better. :(

Since this is failing on subsequent boots, we can actually eliminate
Ignition from the list of potential problems. Ignition only runs on the
first boot, so if it sucessfully boots regularly (which it does in this
case), Ignition is working properly.

I assume your config is as follows:

systemd:
units:

- name: sshd@.service
dropins:
- name: wait-on-etcd.conf
contents: |
[Unit]
After=etcd-member.service

- name: etcd-member.service
enable: true

This means that the most likely point of failure is etcd. If it only
failed on the first boot, I'd guess that rkt was timing out while
fetching etcd. Since that's not the case, there is something else that
eventually fails with etcd.

I would suggest using Ignition to create a second account with a
password that you can use to bypass this just for testing. Once you log
in with that account, you'll be able to investigate why etcd is failing.

-Alex

[Nate Williams]

Alex Crawford writes:
> On 04/19, Nathan Williams wrote:
> > I'm at a standstill, and am looking at adding crappy code to do something
> > like 'sleep 90' at the start of my initial node spinup to avoid the SSH
> > race, since Ignition is giving us no-end of problems. I don't know what
> > the problem, but if I use the exact same configuration and create a node
> > 10x, it will work fine 5 out of the ten times, and it will fail to allow
> > logins 5 of the times. And, even if it spins up correctly the first 5
> > instances, it will eventually fail to allow logins if I reboot it enough
> > times. I've got 40+ hours into trying to make this work, and I'm no
> > further along now than I was last week.
> >
> > This smells very much like a race in how Ignition does it's thing, but b/c
> > the logs aren't very helpful, and the only access I have to the EC2
> > instance is via SSH, it makes it very difficult to debug the issue. So,
> > we're going to give up on Ignition b/c it's just too fragile, and hope it
> > gets better. :(
>
> Since this is failing on subsequent boots, we can actually eliminate
> Ignition from the list of potential problems. Ignition only runs on the
> first boot, so if it sucessfully boots regularly (which it does in this
> case), Ignition is working properly.

Sometimes, but not always.

> I assume your config is as follows:
>
> systemd:
> units:
> - name: sshd@.service
> dropins:
> - name: wait-on-etcd.conf
> contents: |
> [Unit]
> After=etcd-member.service
>
> - name: etcd-member.service
> enable: true

Not exactly, but close. There is an actual service definition for
wait-on-etcd, based on David's posting/email, which I followed
to the letter. And, that service has a 180s timeout, so even if it
fails, it should allow SSH to startup (at least, that's my understanding).

> This means that the most likely point of failure is etcd. If it only
> failed on the first boot, I'd guess that rkt was timing out while
> fetching etcd. Since that's not the case, there is something else that
> eventually fails with etcd.

Sure, but we have a timeout on etcd startup.

> I would suggest using Ignition to create a second account with a
> password that you can use to bypass this just for testing. Once you log
> in with that account, you'll be able to investigate why etcd is failing.

Unfortunately, SSH is disabled, so having another account doesn't help,
since SSHD is blocked from running.



Nate

[Alex Crawford]

On 04/19, Nate Williams wrote:
> Alex Crawford writes:
> > On 04/19, Nathan Williams wrote:
> > Since this is failing on subsequent boots, we can actually eliminate
> > Ignition from the list of potential problems. Ignition only runs on the
> > first boot, so if it sucessfully boots regularly (which it does in this
> > case), Ignition is working properly.
>
> Sometimes, but not always.

I think the root cause of this is the same as in the cases where the
first boot works, but a subsequent boot fails. From what I've seen,
Ignition always runs correctly, but etcd sometimes fails to start. The
cluster may be taking too long to bootstrap which would cause etcd to
fail or if the node reboots before the cluster is established it will
pick up a new node ID and then conflict with the previous attempt, also
killing the bootstrap.

> > I assume your config is as follows:
> >
> > systemd:
> > units:
> > - name: sshd@.service
> > dropins:
> > - name: wait-on-etcd.conf
> > contents: |
> > [Unit]
> > After=etcd-member.service
> >
> > - name: etcd-member.service
> > enable: true
>
> Not exactly, but close. There is an actual service definition for
> wait-on-etcd, based on David's posting/email, which I followed
> to the letter. And, that service has a 180s timeout, so even if it
> fails, it should allow SSH to startup (at least, that's my understanding).

> > I would suggest using Ignition to create a second account with a
> > password that you can use to bypass this just for testing. Once you log
> > in with that account, you'll be able to investigate why etcd is failing.
>
> Unfortunately, SSH is disabled, so having another account doesn't help,
> since SSHD is blocked from running.

Ah, crap. That was a silly suggestion.

I tried this out on EC2 and didn't run into any issues :/
I used this config with a three node cluster:

etcd:
advertise_client_urls: http://{PUBLIC_IPV4}:2379
initial_advertise_peer_urls: http://{PUBLIC_IPV4}:2380
listen_client_urls: http://0.0.0.0:2379
listen_peer_urls: http://0.0.0.0:2380
discovery: https://discovery.etcd.io/token

systemd:
units:
- name: sshd@.service.d
dropins:
- name: wait-for-etcd.conf
[Unit]
Requires=etcd-member.service
After=etcd-member.service

It was actually kinda spiffy. SSH would hang until the moment the
cluster was up and then it would let me in. It also worked if I manually
stopped etcd on two of the three nodes. SSH would hang until I started
up one of them.

-Alex

[Nate Williams]

> On 04/19, Nate Williams wrote:
> > Alex Crawford writes:
> > > On 04/19, Nathan Williams wrote:
> > > Since this is failing on subsequent boots, we can actually eliminate
> > > Ignition from the list of potential problems. Ignition only runs on the
> > > first boot, so if it sucessfully boots regularly (which it does in this
> > > case), Ignition is working properly.
> >
> > Sometimes, but not always.
>
> I think the root cause of this is the same as in the cases where the
> first boot works, but a subsequent boot fails. From what I've seen,
> Ignition always runs correctly, but etcd sometimes fails to start. The
> cluster may be taking too long to bootstrap which would cause etcd to
> fail or if the node reboots before the cluster is established it will
> pick up a new node ID and then conflict with the previous attempt, also
> killing the bootstrap.

I did some investigation yesterday, and I concur. The failures are due
to etcd not starting up properly, which then blocks SSH access.

> I tried this out on EC2 and didn't run into any issues :/
> I used this config with a three node cluster:
>
> etcd:
> advertise_client_urls: http://{PUBLIC_IPV4}:2379
> initial_advertise_peer_urls: http://{PUBLIC_IPV4}:2380
> listen_client_urls: http://0.0.0.0:2379
> listen_peer_urls: http://0.0.0.0:2380
> discovery: https://discovery.etcd.io/token
>
> systemd:
> units:
> - name: sshd@.service.d
> dropins:
> - name: wait-for-etcd.conf
> [Unit]
> Requires=etcd-member.service
> After=etcd-member.service
>
> It was actually kinda spiffy. SSH would hang until the moment the
> cluster was up and then it would let me in. It also worked if I manually
> stopped etcd on two of the three nodes. SSH would hang until I started
> up one of them.

So, that leads me to another question. What I'm looking for is this
behavior *AT FIRST BOOT* (and only first boot). Also, if etcd can't
startup properly, I would like it start SSH, so I want it to effectively
delay SSH connections until either etcd is fully healthy and/or it times
out, whichever comes first.

And, I only need that behavior at first boot. Any good ideas?

Also, I'm not having any luck trying to configure etcd with ignition for
a static environment with hard-coded IPs, but that's a question for
another email.

Thanks for all your help!


Nate

[Alex Crawford]

On 04/23, Nate Williams wrote:
> So, that leads me to another question. What I'm looking for is this
> behavior *AT FIRST BOOT* (and only first boot). Also, if etcd can't
> startup properly, I would like it start SSH, so I want it to effectively
> delay SSH connections until either etcd is fully healthy and/or it times
> out, whichever comes first.

Oof, that makes me nervous. At the limit, SSH logins succeed in either
case. I guess if you made the timeout sufficiently long it would be
managable but I personally would opt for a different solution. either
throwing something it the MOTD (if it's for a human) or making my
automation check `systemctl is-system-running`.

If you still want to go the timeout route, David's script should do
the trick.

> And, I only need that behavior at first boot. Any good ideas?

You can probably use ConditionFirstBoot [1] to make sure that your
service only runs once.

-Alex

[1]: https://www.freedesktop.org/software/systemd/man/systemd.unit.html#ConditionArchitecture=