Maltfield Log/2020 Q3
My work log from the year 2020 Quarter 3. I intentionally made this verbose to make future admin's work easier when troubleshooting. The more keywords, error messages, etc that are listed in this log, the more helpful it will be for the future OSE Sysadmin.
See Also
Sun Jun 27, 2020
1. Rob can ssh into dev but for some reason he can no longer access staging. We had a long call about this, but nothing made sense. Maybe something got corrupt on staging when the dev server suddenly died soe time back. I'll initate a new sync today before our next call (which will be a fresh start since Rob doesn't have a user yet on prod) and see if I can unblock him on our next call. 2. I initiated a sync from prod to staging, but it failed with timeouts. It turns out that the prod server wasn't connected to the VPN. I fixed it and added a bit to the documentation with troubleshooting commands to check for this and fix it https://wiki.opensourceecology.org/wiki/OSE_Staging_Server#Troubleshooting 3. After the vpn issues were resolved, I tried the sync again. This time it failed with permission denied.
[root@opensourceecology client]# tail -f /var/log/syncToStaging.log ... + nice rsync -e 'ssh -p 32415 -i /root/.ssh/id_rsa.201910' --bwlimit=3000 --numeric-ids --delete '--rsync-path=sudo rsync' --exclude=/root --exclude=/run '--exclude=/home/b2user/sync*' '--exclude=/home/stagingsync*' '--exclude=/etc/sudo*' --exclude=/etc/group --exclude=/etc/openvpn --exclude=/usr/share/easy-rsa --exclude=/dev --exclude=/sys --exclude=/proc --exclude=/boot/ '--exclude=/etc/sysconfig/network*' --exclude=/tmp --exclude=/var/tmp --exclude=/etc/fstab --exclude=/etc/mtab --exclude=/etc/mdadm.conf --exclude=/etc/hostname -av --progress / stagingsync@10.241.189.11:/ Permission denied (publickey). rsync: connection unexpectedly closed (0 bytes received so far) [sender] rsync error: unexplained error (code 255) at io.c(226) [sender=3.1.2] real 0m0.205s user 0m0.035s sys 0m0.010s
5. Shit, this is the same issue that Rob was having. Am I in a catch-22? I tried to ssh-in as the 'stagingsync' user directly. Same error
[root@opensourceecology ~]# ssh -v -p32415 stagingsync@10.241.189.11 OpenSSH_7.4p1, OpenSSL 1.0.2k-fips 26 Jan 2017 debug1: Reading configuration data /etc/ssh/ssh_config debug1: /etc/ssh/ssh_config line 56: Applying options for * debug1: Connecting to 10.241.189.11 [10.241.189.11] port 32415. debug1: Connection established. debug1: permanently_set_uid: 0/0 debug1: identity file /root/.ssh/id_rsa type 1 debug1: key_load_public: No such file or directory debug1: identity file /root/.ssh/id_rsa-cert type -1 debug1: key_load_public: No such file or directory debug1: identity file /root/.ssh/id_dsa type -1 debug1: key_load_public: No such file or directory debug1: identity file /root/.ssh/id_dsa-cert type -1 debug1: key_load_public: No such file or directory debug1: identity file /root/.ssh/id_ecdsa type -1 debug1: key_load_public: No such file or directory debug1: identity file /root/.ssh/id_ecdsa-cert type -1 debug1: key_load_public: No such file or directory debug1: identity file /root/.ssh/id_ed25519 type -1 debug1: key_load_public: No such file or directory debug1: identity file /root/.ssh/id_ed25519-cert type -1 debug1: Enabling compatibility mode for protocol 2.0 debug1: Local version string SSH-2.0-OpenSSH_7.4 debug1: Remote protocol version 2.0, remote software version OpenSSH_7.4 debug1: match: OpenSSH_7.4 pat OpenSSH* compat 0x04000000 debug1: Authenticating to 10.241.189.11:32415 as 'stagingsync' debug1: SSH2_MSG_KEXINIT sent debug1: SSH2_MSG_KEXINIT received debug1: kex: algorithm: curve25519-sha256 debug1: kex: host key algorithm: ecdsa-sha2-nistp521 debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none debug1: kex: curve25519-sha256 need=64 dh_need=64 debug1: kex: curve25519-sha256 need=64 dh_need=64 debug1: expecting SSH2_MSG_KEX_ECDH_REPLY debug1: Server host key: ecdsa-sha2-nistp521 SHA256:HclF8ZQOjGqx+9TmwL111kZ7QxgKkoEw8g3l2YxV0gk debug1: Host '[10.241.189.11]:32415' is known and matches the ECDSA host key. debug1: Found key in /root/.ssh/known_hosts:6 debug1: rekey after 134217728 blocks debug1: SSH2_MSG_NEWKEYS sent debug1: expecting SSH2_MSG_NEWKEYS debug1: SSH2_MSG_NEWKEYS received debug1: rekey after 134217728 blocks debug1: SSH2_MSG_EXT_INFO received debug1: kex_input_ext_info: server-sig-algs=<rsa-sha2-256,rsa-sha2-512> debug1: SSH2_MSG_SERVICE_ACCEPT received debug1: Authentications that can continue: publickey debug1: Next authentication method: publickey debug1: Offering RSA public key: /root/.ssh/id_rsa debug1: Authentications that can continue: publickey debug1: Trying private key: /root/.ssh/id_dsa debug1: Trying private key: /root/.ssh/id_ecdsa debug1: Trying private key: /root/.ssh/id_ed25519 debug1: No more authentication methods to try. Permission denied (publickey). [root@opensourceecology ~]#
7. I still have debugging turned-on on the server-side (staging's sshd daemon), and here's what it logs during the above request to /var/log/secure
Sep 27 09:39:51 osestaging1 sshd[314]: debug3: fd 5 is not O_NONBLOCK Sep 27 09:39:51 osestaging1 sshd[314]: debug1: Forked child 7188. Sep 27 09:39:51 osestaging1 sshd[314]: debug3: send_rexec_state: entering fd = 8 config len 885 Sep 27 09:39:51 osestaging1 sshd[314]: debug3: ssh_msg_send: type 0 Sep 27 09:39:51 osestaging1 sshd[314]: debug3: send_rexec_state: done Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: oom_adjust_restore Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: Set /proc/self/oom_score_adj to 0 Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: rexec start in 5 out 5 newsock 5 pipe 7 sock 8 Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: inetd sockets after dupping: 3, 3 Sep 27 09:39:51 osestaging1 sshd[7188]: Connection from 10.241.189.10 port 40424 on 10.241.189.11 port 32415 Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: Client protocol version 2.0; client software version OpenSSH_7.4 Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: match: OpenSSH_7.4 pat OpenSSH* compat 0x04000000 Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: Local version string SSH-2.0-OpenSSH_7.4 Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: Enabling compatibility mode for protocol 2.0 Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: fd 3 setting O_NONBLOCK Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: ssh_sandbox_init: preparing seccomp filter sandbox Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: Network child is on pid 7189 Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: preauth child monitor started Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: SELinux support disabled [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: privsep user:group 74:74 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: permanently_set_uid: 74/74 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: ssh_sandbox_child: setting PR_SET_NO_NEW_PRIVS [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: ssh_sandbox_child: attaching seccomp filter program [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: list_hostkey_types: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp521,ssh-ed25519 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: send packet: type 20 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: SSH2_MSG_KEXINIT sent [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: receive packet: type 20 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: SSH2_MSG_KEXINIT received [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: local server KEXINIT proposal [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: host key algorithms: ssh-rsa,rsa-sha2-512,rsa-sha2-256,ecdsa-sha2-nistp521,ssh-ed25519 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,cast128-cbc,3des-cbc [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc,blowfish-cbc,cast128-cbc,3des-cbc [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: compression ctos: none,zlib@openssh.com [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: compression stoc: none,zlib@openssh.com [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: languages ctos: [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: languages stoc: [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: first_kex_follows 0 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: reserved 0 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: peer client KEXINIT proposal [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: KEX algorithms: curve25519-sha256,curve25519-sha256@libssh.org,ecdh-sha2-nistp256,ecdh-sha2-nistp384,ecdh-sha2-nistp521,diffie-hellman-group-exchange-sha256,diffie-hellman-group16-sha512,diffie-hellman-group18-sha512,diffie-hellman-group-exchange-sha1,diffie-hellman-group14-sha256,diffie-hellman-group14-sha1,diffie-hellman-group1-sha1,ext-info-c [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: host key algorithms: ecdsa-sha2-nistp256-cert-v01@openssh.com,ecdsa-sha2-nistp384-cert-v01@openssh.com,ecdsa-sha2-nistp521-cert-v01@openssh.com,ecdsa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,ssh-ed25519-cert-v01@openssh.com,ssh-rsa-cert-v01@openssh.com,ssh-dss-cert-v01@openssh.com,ssh-ed25519,rsa-sha2-512,rsa-sha2-256,ssh-rsa,ssh-dss [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: ciphers ctos: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: ciphers stoc: chacha20-poly1305@openssh.com,aes128-ctr,aes192-ctr,aes256-ctr,aes128-gcm@openssh.com,aes256-gcm@openssh.com,aes128-cbc,aes192-cbc,aes256-cbc [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: MACs ctos: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: MACs stoc: umac-64-etm@openssh.com,umac-128-etm@openssh.com,hmac-sha2-256-etm@openssh.com,hmac-sha2-512-etm@openssh.com,hmac-sha1-etm@openssh.com,umac-64@openssh.com,umac-128@openssh.com,hmac-sha2-256,hmac-sha2-512,hmac-sha1 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: compression ctos: none,zlib@openssh.com,zlib [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: compression stoc: none,zlib@openssh.com,zlib [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: languages ctos: [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: languages stoc: [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: first_kex_follows 0 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: reserved 0 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: kex: algorithm: curve25519-sha256 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: kex: host key algorithm: ecdsa-sha2-nistp521 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: kex: client->server cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: kex: server->client cipher: chacha20-poly1305@openssh.com MAC: <implicit> compression: none [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: kex: curve25519-sha256 need=64 dh_need=64 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 120 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive_expect entering: type 121 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive entering [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: monitor_read: checking request 120 Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 121 Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: kex: curve25519-sha256 need=64 dh_need=64 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 120 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive_expect entering: type 121 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive entering [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: monitor_read: checking request 120 Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 121 Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: expecting SSH2_MSG_KEX_ECDH_INIT [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: receive packet: type 30 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_key_sign entering [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 6 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_key_sign: waiting for MONITOR_ANS_SIGN [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive_expect entering: type 7 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive entering [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: monitor_read: checking request 6 Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_answer_sign Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_answer_sign: hostkey proof signature 0x557b692700b0(167) Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 7 Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: monitor_read: 6 used once, disabling now Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: send packet: type 31 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: send packet: type 21 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: set_newkeys: mode 1 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: rekey after 134217728 blocks [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: SSH2_MSG_NEWKEYS sent [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: expecting SSH2_MSG_NEWKEYS [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: send packet: type 7 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: receive packet: type 21 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: SSH2_MSG_NEWKEYS received [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: set_newkeys: mode 0 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: rekey after 134217728 blocks [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: KEX done [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: receive packet: type 5 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: send packet: type 6 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: receive packet: type 50 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: userauth-request for user stagingsync service ssh-connection method none [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: attempt 0 failures 0 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_getpwnamallow entering [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 8 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_getpwnamallow: waiting for MONITOR_ANS_PWNAM [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive_expect entering: type 9 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive entering [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: monitor_read: checking request 8 Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_answer_pwnamallow Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: Trying to reverse map address 10.241.189.10. Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: parse_server_config: config reprocess config len 885 Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_answer_pwnamallow: sending MONITOR_ANS_PWNAM: 1 Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 9 Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: monitor_read: 8 used once, disabling now Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: input_userauth_request: setting up authctxt for stagingsync [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_start_pam entering [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 100 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_inform_authserv entering [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 4 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_inform_authrole entering [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 80 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: input_userauth_request: try method none [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: userauth_finish: failure partial=0 next methods="publickey" [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: send packet: type 51 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: monitor_read: checking request 100 Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: PAM: initializing for "stagingsync" Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: PAM: setting PAM_RHOST to "10.241.189.10" Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: PAM: setting PAM_TTY to "ssh" Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: monitor_read: 100 used once, disabling now Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: receive packet: type 50 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: userauth-request for user stagingsync service ssh-connection method publickey [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: attempt 1 failures 0 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug2: input_userauth_request: try method publickey [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug1: userauth_pubkey: test whether pkalg/pkblob are acceptable for RSA SHA256:/LpjdDSJFVAt0a4d2PM3fWu7ci3VVwqQT0UxobZel2s [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_key_allowed entering [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 22 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_key_allowed: waiting for MONITOR_ANS_KEYALLOWED [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive_expect entering: type 23 [preauth] Sep 27 09:39:51 osestaging1 sshd[7188]: debug3: mm_request_receive entering [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: monitor_read: checking request 4 Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_answer_authserv: service=ssh-connection, style= Sep 27 09:39:52 osestaging1 sshd[7188]: debug2: monitor_read: 4 used once, disabling now Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: monitor_read: checking request 80 Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_answer_authrole: role= Sep 27 09:39:52 osestaging1 sshd[7188]: debug2: monitor_read: 80 used once, disabling now Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: monitor_read: checking request 22 Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_answer_keyallowed entering Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_answer_keyallowed: key_from_blob: 0x557b6927dea0 Sep 27 09:39:52 osestaging1 sshd[7188]: debug1: temporarily_use_uid: 1014/1015 (e=0/0) Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_answer_keyallowed: key 0x557b6927dea0 is not allowed Sep 27 09:39:52 osestaging1 sshd[7188]: Failed publickey for stagingsync from 10.241.189.10 port 40424 ssh2: RSA SHA256:/LpjdDSJFVAt0a4d2PM3fWu7ci3VVwqQT0UxobZel2s Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 23 Sep 27 09:39:52 osestaging1 sshd[7188]: debug2: userauth_pubkey: authenticated 0 pkalg rsa-sha2-512 [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: userauth_finish: failure partial=0 next methods="publickey" [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: send packet: type 51 [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: Connection closed by 10.241.189.10 port 40424 [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: debug1: do_cleanup [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: PAM: sshpam_thread_cleanup entering [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 124 [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 122 [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_receive_expect entering: type 123 [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_receive entering [preauth] Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: monitor_read: checking request 124 Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: monitor_read: checking request 122 Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_send entering: type 123 Sep 27 09:39:52 osestaging1 sshd[7188]: debug1: monitor_read_log: child log fd closed Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: mm_request_receive entering Sep 27 09:39:52 osestaging1 sshd[7188]: debug1: do_cleanup Sep 27 09:39:52 osestaging1 sshd[7188]: debug1: PAM: cleanup Sep 27 09:39:52 osestaging1 sshd[7188]: debug3: PAM: sshpam_thread_cleanup entering Sep 27 09:39:52 osestaging1 sshd[7188]: debug1: Killing privsep child 7189 Sep 27 09:40:01 osestaging1 su: pam_unix(su:session): session opened for user apache by (uid=0) Sep 27 09:40:01 osestaging1 su: pam_unix(su:session): session closed for user apache
9. It feels like something is just horribly corrupt; I can't even restart ssh. I get this weird DBus error
[root@osestaging1 ~]# systemctl restart sshd ** (pkttyagent:7553): WARNING **: 09:43:45.339: Unable to register authentication agent: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.PolicyKit1 was not provided by any .service files Error registering authentication agent: GDBus.Error:org.freedesktop.DBus.Error.ServiceUnknown: The name org.freedesktop.PolicyKit1 was not provided by any .service files (g-dbus-error-quark, 2) [root@osestaging1 ~]#
11. I tried reinstalling all the ssh packages from yum; it didn't help
[root@osestaging1 ~]# rpm -qa | grep ssh libssh2-1.8.0-3.el7.x86_64 openssh-server-7.4p1-21.el7.x86_64 openssh-7.4p1-21.el7.x86_64 openssh-clients-7.4p1-21.el7.x86_64 [root@osestaging1 ~]# yum reinstall libssh2 openssh-server openssh openssh-clients ... Installed: libssh2.x86_64 0:1.8.0-3.el7 openssh.x86_64 0:7.4p1-21.el7 openssh-clients.x86_64 0:7.4p1-21.el7 openssh-server.x86_64 0:7.4p1-21.el7 Complete! [root@osestaging1 ~]#
13. I found that if I execute the ssh daemon command directy with three -d arguments, then I get a bit more output. most importantly, I get a permission deneid eror when attempting to ccess the user's "authorized_keys" file, which makes sense as to why the login would fail
15. I started poking at the permissions in /home, and I discovered that the root directory (/) is owned by not-apache:apache with 0050 permissions. That's an issue!
[root@osestaging1 ~]# ls -lah /home total 60K drwxr-xr-x. 15 root root 4.0K May 10 19:06 . d---r-x---. 21 not-apache apache 4.0K Aug 14 13:09 .. ... drwx------. 3 stagingsync stagingsync 4.0K Oct 24 2019 stagingsync ...
17. Note that on prod this is root:root 0555 18. I tried changing it, but things quickly got worse on my ssh connection. Now shit's totally fucked
[maltfield@osestaging1 ~]$ sudo su - -bash: /usr/bin/sudo: Permission denied [maltfield@osestaging1 ~]$ df -h -bash: df: command not found [maltfield@osestaging1 ~]$ ls -lah / -bash: ls: command not found [maltfield@osestaging1 ~]$ screen -dr sync -bash: /usr/bin/screen: Permission denied [maltfield@osestaging1 ~]$
20. I tried to login to the hetzner console, but it said my creds were wrong. I tried reset my pass, but it said my account was locked-out. WTF?
21. I was successfully able to login with the OSE shared account in our shared keepass file.
a. I confirmed that we have zero snapshots and zero backups of the dev/staging server on hetzner cloud's side
b. snapshots are 0.01 EUR/GB/month. Our dev server is 20G (though it uses an attached disk at /var/ that's 127G, and is where staging lives), I think it's worthwhile to spend ~3 EUR/year for a snapshot of dev
22. anyway, the staging server is just an lxc container on dev. I connected to it and opened the tty to the staging server. Interestingly, it had some errors on its last boot (I'm betting corruption still)
[/etc/systemd/system/openvpn-client.service:2] Failed to resolve unit specifiers on OpenVPN tunnel for %I, ignoring: Success ... [ OK ] Started Create Volatile Files and Directories. Starting Security Auditing Service... [FAILED] Failed to start Security Auditing Service. See 'systemctl status auditd.service' for details. Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. ... [ OK ] Started irqbalance daemon. Starting ACPI Event Daemon... [FAILED] Failed to start Authorization Manager. See 'systemctl status polkit.service' for details. [DEPEND] Dependency failed for Dynamic System Tuning Daemon. [ OK ] Started Run automatic yum updates as a cron job. [FAILED] Failed to start NTP client/server. See 'systemctl status chronyd.service' for details. [ OK ] Started Permit User Sessions. ... Starting openvpn-client.service... [FAILED] Failed to start MariaDB database server. See 'systemctl status mariadb.service' for details.
24. I was unable to login to the tty as maltfield or root
osestaging1 login: maltfield Password: Last failed login: Sun Sep 27 10:14:25 UTC 2020 on lxc/console There was 1 failed login attempt since the last successful login. Last login: Sun Sep 27 09:17:36 from 10.241.189.50 -- maltfield: /home/maltfield: change directory failed: Permission denied
26. I tried stopping & starting the lxc container; I still had the boot issues and couldn't login 27. I stopped the container again and checked the permissions. I think I discovered my error. It looks like I changed the owner to root:root and then everything broke before I could change the permissions from 0050 to 0555
[root@osedev1 ~]# ls -lah /var/lib/lxc/osestaging1/rootfs | head -n3 total 2.1G d---r-x---. 21 root root 4.0K Sep 27 12:21 . drwxrwx---. 5 root root 4.0K Sep 27 12:21 .. [root@osedev1 ~]#
29. I changed the ownership and started it again; this time most of the boot errors went away and I was able to login!
[root@osedev1 ~]# chown root /var/lib/lxc/osestaging1/rootfs/ [root@osedev1 ~]# chmod 0555 /var/lib/lxc/osestaging1/rootfs/ [root@osedev1 ~]# ls -lah /var/lib/lxc/osestaging1/rootfs | head -n3 total 2.1G dr-xr-xr-x. 21 root root 4.0K Sep 27 12:26 . drwxrwx---. 5 root root 4.0K Sep 27 12:26 .. [root@osedev1 ~]# lxc-start --name osestaging1 osestaging1 login: maltfield Password: Last failed login: Sun Sep 27 10:31:05 UTC 2020 on lxc/console There was 1 failed login attempt since the last successful login. Last login: Sun Sep 27 10:27:23 on lxc/console [maltfield@osestaging1 ~]$
31. I was able to ssh back in, start a screen, become root, and restart the ssh service. good.
[root@osestaging1 ~]# systemctl list-units | grep -i ssh sshd.service loaded active running OpenSSH server daemon [root@osestaging1 ~]# systemctl restart sshd [root@osestaging1 ~]#
33. For some reason there's an htdocs dir in the root of the fs too. My best guess is kludged an rsync command over '/' from prod to staging in the past when trying to fix a corruption issue of the wordpress sites when Rob discovered some issues with it.
[root@osestaging1 ~]# ls -lah / total 2.1G dr-xr-xr-x. 21 root root 4.0K Sep 27 10:30 . dr-xr-xr-x. 21 root root 4.0K Sep 27 10:30 .. ... d---r-x---. 7 not-apache apache 4.0K May 7 17:24 htdocs ----r-----. 1 not-apache apache-admins 4.4K Oct 3 2018 wp-config.php [root@osestaging1 ~]#
35. I finally got ssh access again, but I had to harden the permissons on the authorized_keys file again
[root@opensourceecology ~]# ssh -p32415 -i /root/.ssh/id_rsa.201910 stagingsync@10.241.189.11 debug3: mm_request_send entering: type 124 Last login: Sun Sep 27 10:44:52 2020 from 10.241.189.10 debug3: Copy environment: XDG_SESSION_ID=100440 Environment: LANG=en_US.UTF-8 USER=stagingsync LOGNAME=stagingsync HOME=/home/stagingsync PATH=/usr/local/bin:/usr/bin MAIL=/var/mail/stagingsync SHELL=/bin/bash SSH_CLIENT=10.241.189.10 52146 32415 SSH_CONNECTION=10.241.189.10 52146 10.241.189.11 32415 SSH_TTY=/dev/pts/5 TERM=screen XDG_SESSION_ID=100440 [stagingsync@osestaging1 ~]$
37. before I kick-off a sync, I'm going to ask Rob to try to login again
Mon Jun 15, 2020
1. Rob mentioned he couldn't get into staging 2. I checked and it was down 3. I checked the dev node, and all my screens were gone. Uptime is listed as 13 minutes?!? 4. I launched a new screen and started the staging server with the lxc-start command
screen -S staging lxc-start --name osestaging1
6. I still couldn't get to the staing sites, dns didn't return anything
user@ose:~/openvpn$ echo "nameserver 10.241.189.1" | sudo tee /etc/resolv.conf nameserver 10.241.189.1 user@ose:~/openvpn$ dig opensourceecology.org
- <<>> DiG 9.10.3-P4-Debian <<>> opensourceecology.org
- global options
- +cmd
- connection timed out; no servers could be reached
user@ose:~/openvpn$
8. looks like dnsmasq isn't setup to start on booot on the dev node; I changed that
[maltfield@osedev1 ~]$ sudo su - Last login: Mon Jun 15 14:56:22 CEST 2020 on pts/2 [root@osedev1 ~]# systemctl list-unit-files | grep dnsm dnsmasq.service disabled [root@osedev1 ~]# systemctl enable dnsmasq.service Created symlink from /etc/systemd/system/multi-user.target.wants/dnsmasq.service to /usr/lib/systemd/system/dnsmasq.service. [root@osedev1 ~]# systemctl list-unit-files | grep dnsm dnsmasq.service enabled [root@osedev1 ~]# systemctl start dnsmasq.service [root@osedev1 ~]#
10. now dns works
user@ose:~/openvpn$ dig opensourceecology.org
- <<>> DiG 9.10.3-P4-Debian <<>> opensourceecology.org
- global options
- +cmd
- Got answer
- ->>HEADER<<- opcode
- QUERY, status: NOERROR, id: 62798
- flags
- qr aa rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1
- OPT PSEUDOSECTION
- EDNS
- version: 0, flags:; udp: 4096
- QUESTION SECTION
- opensourceecology.org. IN A
- ANSWER SECTION
opensourceecology.org. 0 IN A 10.241.189.11
- Query time
- 172 msec
- SERVER
- 10.241.189.1#53(10.241.189.1)
- WHEN
- Mon Jun 15 18:51:58 +0545 2020
- MSG SIZE rcvd
- 66
user@ose:~/openvpn$
12. The first entry in the journalctl on the dev server starts at June 15 (today) at 01:50:03
[root@osedev1 ~]# journalctl | head -- Logs begin at Mon 2020-06-15 01:50:03 CEST, end at Mon 2020-06-15 15:07:45 CEST. -- Jun 15 01:50:03 localhost systemd-journal[101]: Runtime journal is using 8.0M (max allowed 89.5M, trying to leave 134.2M free of 887.0M available → current limit 89.5M). Jun 15 01:50:03 localhost kernel: Initializing cgroup subsys cpuset Jun 15 01:50:03 localhost kernel: Initializing cgroup subsys cpu Jun 15 01:50:03 localhost kernel: Initializing cgroup subsys cpuacct Jun 15 01:50:03 localhost kernel: Linux version 3.10.0-957.21.3.el7.x86_64 (mockbuild@kbuilder.bsys.centos.org) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-36) (GCC) ) #1 SMP Tue Jun 18 16:35:19 UTC 2019 Jun 15 01:50:03 localhost kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-3.10.0-957.21.3.el7.x86_64 root=UUID=1e457b76-5100-4b53-bcdc-667ca122b941 ro crashkernel=auto consoleblank=0 systemd.show_status=true elevator=noop console=tty1 console=ttyS0 Jun 15 01:50:03 localhost kernel: e820: BIOS-provided physical RAM map: Jun 15 01:50:03 localhost kernel: BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable Jun 15 01:50:03 localhost kernel: BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [root@osedev1 ~]#
14. the entries preceeding that in /var/log/messages aren't very helpful
Jun 15 00:56:34 osedev1 chronyd[674]: System clock wrong by -3.278855 seconds, adjustment started Jun 15 00:57:39 osedev1 chronyd[674]: System clock wrong by -1.017910 seconds, adjustment started Jun 15 00:58:44 osedev1 chronyd[674]: System clock wrong by 1.292079 seconds, adjustment started Jun 15 00:59:49 osedev1 chronyd[674]: System clock wrong by -1.323920 seconds, adjustment started Jun 15 01:01:01 osedev1 systemd: Created slice User Slice of root. Jun 15 01:01:01 osedev1 systemd: Started Session 205569 of user root. Jun 15 01:01:01 osedev1 systemd: Removed slice User Slice of root. Jun 15 01:01:59 osedev1 chronyd[674]: System clock wrong by 1.104784 seconds, adjustment started Jun 15 01:02:08 osedev1 chronyd[674]: Can't synchronise: no majority Jun 15 01:02:08 osedev1 chronyd[674]: Selected source 193.30.35.11 Jun 15 01:02:11 osedev1 chronyd[674]: Can't synchronise: no majority Jun 15 01:03:04 osedev1 chronyd[674]: Selected source 176.9.103.244 Jun 15 01:03:13 osedev1 chronyd[674]: Selected source 193.30.35.11 Jun 15 01:03:15 osedev1 chronyd[674]: Can't synchronise: no majority Jun 15 01:04:08 osedev1 chronyd[674]: Selected source 176.9.103.244 Jun 15 01:04:17 osedev1 chronyd[674]: Selected source 193.30.35.11 Jun 15 01:04:20 osedev1 chronyd[674]: Can't synchronise: no majority Jun 15 01:05:13 osedev1 chronyd[674]: Selected source 2a02:c207:3003:930::1 Jun 15 01:05:22 osedev1 chronyd[674]: Can't synchronise: no majority Jun 15 01:09:30 osedev1 chronyd[674]: Selected source 176.9.103.244 Jun 15 01:09:30 osedev1 chronyd[674]: System clock wrong by 1.213375 seconds, adjustment started Jun 15 01:12:55 osedev1 chronyd[674]: Can't synchronise: no majority Jun 15 01:12:56 osedev1 chronyd[674]: Selected source 193.30.35.11 Jun 15 01:14:50 osedev1 dnsmasq-dhcp[1346]: DHCPREQUEST(virbr0) 192.168.122.201 fe:07:06:a6:5f:1d Jun 15 01:14:50 osedev1 dnsmasq-dhcp[1346]: DHCPACK(virbr0) 192.168.122.201 fe:07:06:a6:5f:1d osestaging1 Jun 15 01:16:09 osedev1 chronyd[674]: Selected source 176.9.103.244 Jun 15 01:16:09 osedev1 chronyd[674]: Selected source 195.201.19.162 Jun 15 01:17:13 osedev1 chronyd[674]: Can't synchronise: no majority Jun 15 01:17:15 osedev1 chronyd[674]: Selected source 193.30.35.11 Jun 15 01:19:15 osedev1 chronyd[674]: Selected source 2a02:c207:3003:930::1 Jun 15 01:19:22 osedev1 chronyd[674]: Can't synchronise: no majority Jun 15 01:20:19 osedev1 chronyd[674]: Selected source 193.30.35.11 Jun 15 01:20:26 osedev1 chronyd[674]: Can't synchronise: no majority Jun 15 01:22:28 osedev1 chronyd[674]: Selected source 193.30.35.11 Jun 15 01:25:42 osedev1 chronyd[674]: Source 176.9.103.244 replaced with 213.209.109.44 Jun 15 01:28:56 osedev1 chronyd[674]: Selected source 213.209.109.44 Jun 15 01:31:06 osedev1 chronyd[674]: Can't synchronise: no selectable sources Jun 15 01:34:21 osedev1 chronyd[674]: Selected source 213.209.109.44 Jun 15 01:36:29 osedev1 chronyd[674]: Can't synchronise: no selectable sources Jun 15 01:36:50 osedev1 dnsmasq-dhcp[1346]: DHCPREQUEST(virbr0) 192.168.122.201 fe:07:06:a6:5f:1d Jun 15 01:36:50 osedev1 dnsmasq-dhcp[1346]: DHCPACK(virbr0) 192.168.122.201 fe:07:06:a6:5f:1d osestaging1 Jun 15 01:37:34 osedev1 chronyd[674]: Selected source 213.209.109.44 Jun 15 01:37:34 osedev1 chronyd[674]: System clock wrong by 1.293791 seconds, adjustment started Jun 15 01:50:03 osedev1 kernel: Initializing cgroup subsys cpuset Jun 15 01:50:03 osedev1 kernel: Initializing cgroup subsys cpu
16. meanwhile, I still can't get to the server on staging as nginx is stopped, but just a simple nginx restart fixed it *shrug*
[maltfield@osestaging1 ~]$ systemctl status nginx ● nginx.service - The nginx HTTP and reverse proxy server
Loaded: loaded (/usr/lib/systemd/system/nginx.service; enabled; vendor preset: disabled) Active: failed (Result: exit-code) since Mon 2020-06-15 12:56:46 UTC; 13min ago Process: 343 ExecStartPre=/usr/sbin/nginx -t (code=exited, status=1/FAILURE) Process: 327 ExecStartPre=/usr/bin/rm -f /run/nginx.pid (code=exited, status=0/SUCCESS)
Jun 15 12:56:46 osestaging1 nginx[343]: nginx: [warn] the "ssl" directive is deprecated, use the "listen ...de:11 Jun 15 12:56:46 osestaging1 nginx[343]: nginx: [warn] the "ssl" directive is deprecated, use the "listen ...de:11 Jun 15 12:56:46 osestaging1 nginx[343]: nginx: [warn] conflicting server name "_" on 10.241.189.11:443, ignored Jun 15 12:56:46 osestaging1 nginx[343]: nginx: the configuration file /etc/nginx/nginx.conf syntax is ok Jun 15 12:56:46 osestaging1 systemd[1]: nginx.service: control process exited, code=exited status=1 Jun 15 12:56:46 osestaging1 nginx[343]: nginx: [emerg] bind() to 10.241.189.11:4443 failed (99: Cannot as...ress) Jun 15 12:56:46 osestaging1 nginx[343]: nginx: configuration file /etc/nginx/nginx.conf test failed Jun 15 12:56:46 osestaging1 systemd[1]: Failed to start The nginx HTTP and reverse proxy server. Jun 15 12:56:46 osestaging1 systemd[1]: Unit nginx.service entered failed state. Jun 15 12:56:46 osestaging1 systemd[1]: nginx.service failed. Hint: Some lines were ellipsized, use -l to show in full. Last login: Sun Jun 14 21:02:44 UTC 2020 on pts/1 [root@osestaging1 ~]# systemctl restart nginx [root@osestaging1 ~]#
18. Anyway, high availability on dev/staging isn't really a priority, so whatever. If this is our first outage and it was fixable in 20 minutes, it's fine.
19. Rob is unblocked; I asked him to continue on his wordpress upgrade task and let me know if he encounteres any other issues
