[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]

Re: [tor-bugs] #31916 [Internal Services/Tor Sysadmin Team]: reliability issues with hetzner-nbg1-01

To: undisclosed-recipients: ;
Subject: Re: [tor-bugs] #31916 [Internal Services/Tor Sysadmin Team]: reliability issues with hetzner-nbg1-01
From: "Tor Bug Tracker & Wiki" <blackhole@xxxxxxxxxxxxxx>
Date: Wed, 02 Oct 2019 19:45:02 -0000
Auto-submitted: auto-generated
Delivered-to: archiver@xxxxxxxx
Delivery-date: Wed, 02 Oct 2019 15:45:13 -0400
In-reply-to: <047.09debacfbe5cd669c9e912e2d70f3d7e@torproject.org>
List-archive: <http://lists.torproject.org/pipermail/tor-bugs/>
List-help: <mailto:tor-bugs-request@lists.torproject.org?subject=help>
List-id: "auto: Tor bug tracker status mails" <tor-bugs.lists.torproject.org>
List-post: <mailto:tor-bugs@lists.torproject.org>
List-subscribe: <https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs>, <mailto:tor-bugs-request@lists.torproject.org?subject=subscribe>
List-unsubscribe: <https://lists.torproject.org/cgi-bin/mailman/options/tor-bugs>, <mailto:tor-bugs-request@lists.torproject.org?subject=unsubscribe>
References: <047.09debacfbe5cd669c9e912e2d70f3d7e@torproject.org>
Reply-to: no-reply@xxxxxxxxxxxxxx, tor-assistants@xxxxxxxxxxxxxx
Sender: "tor-bugs" <tor-bugs-bounces@xxxxxxxxxxxxxxxxxxxx>

#31916: reliability issues with hetzner-nbg1-01
-------------------------------------------------+-------------------------
 Reporter:  anarcat                              |          Owner:  anarcat
     Type:  defect                               |         Status:
                                                 |  assigned
 Priority:  Medium                               |      Milestone:
Component:  Internal Services/Tor Sysadmin Team  |        Version:
 Severity:  Blocker                              |     Resolution:
 Keywords:                                       |  Actual Points:
Parent ID:                                       |         Points:
 Reviewer:                                       |        Sponsor:
-------------------------------------------------+-------------------------

Comment (by anarcat):

 i saw a case of a downtime, live. both server couldn't ping each other for
 a few minutes. this happened in the logs, on nbg1:

 {{{
 Oct  2 19:03:20 hetzner-nbg1-01/hetzner-nbg1-01 charon[963]: 09[IKE]
 establishing CHILD_SA hetzner-hel1-01.torproject.org-hetzner-
 nbg1-01.torproject.org{6}
 Oct  2 19:03:26 hetzner-nbg1-01/hetzner-nbg1-01 charon[963]: 08[IKE]
 95.216.141.241 is initiating an IKE_SA
 Oct  2 19:03:26 hetzner-nbg1-01/hetzner-nbg1-01 charon[963]: 13[IKE]
 IKE_SA hetzner-hel1-01.torproject.org-hetzner-nbg1-01.torproject.org[54]
 established between
 195.201.139.202[195.201.139.202]...95.216.141.241[95.216.141.241]
 Oct  2 19:03:26 hetzner-nbg1-01/hetzner-nbg1-01 charon[963]: 13[IKE]
 CHILD_SA hetzner-hel1-01.torproject.org-hetzner-
 nbg1-01.torproject.org{164} established with SPIs c0bc9534_i cf59efd5_o
 and TS 195.201.139.202/32 2a01:4f8:c2c:1e17::1/128 === 95.216.141.241/32
 2a01:4f9:c010:5f1::1/128
 }}}

 ... ie. a new session, negociated in 6 seconds. that's pretty slow, but
 tolerable I guess. the problem is that, from nagios' point of view, this
 was a much longer downtime:

 {{{
 Oct  2 18:57:31 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 10[IKE]
 establishing CHILD_SA hetzner-hel1-01.torproject.org-hetzner-
 nbg1-01.torproject.org{6}
 Oct  2 19:00:16 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 16[IKE]
 initiating IKE_SA hetzner-hel1-01.torproject.org-hetzner-
 nbg1-01.torproject.org[44] to 195.201.139
 .202
 }}}

 ie. the session started 6 *minutes* earlier, and took 3 *more* minutes to
 get to the initiating stage. then nagios noticed the node was down,
 naturally:

 {{{
 Oct  2 19:01:11 hetzner-hel1-01/hetzner-hel1-01 icinga[1469]: SERVICE
 ALERT: hetzner-nbg1-01;process - apache2 -
 worker;CRITICAL;SOFT;1;CHECK_NRPE STATE CRITICAL: Sock
 et timeout after 50 seconds.
 Oct  2 19:01:31 hetzner-hel1-01/hetzner-hel1-01 icinga[1469]: HOST ALERT:
 hetzner-nbg1-01;DOWN;SOFT;1;PING CRITICAL - Packet loss = 100%
 }}}

 then, another three minutes later, ipsec figured it out and fixed the
 outage:

 {{{
 Oct  2 19:03:02 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 12[IKE]
 initiating IKE_SA hetzner-hel1-01.torproject.org-hetzner-
 nbg1-01.torproject.org[45] to 195.201.139.202
 Oct  2 19:03:26 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 14[IKE]
 establishing CHILD_SA hetzner-hel1-01.torproject.org-hetzner-
 nbg1-01.torproject.org{6}
 Oct  2 19:03:26 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 08[IKE]
 IKE_SA hetzner-hel1-01.torproject.org-hetzner-nbg1-01.torproject.org[45]
 established between
 95.216.141.241[95.216.141.241]...195.201.139.202[195.201.139.202]
 Oct  2 19:03:26 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 08[IKE]
 CHILD_SA hetzner-hel1-01.torproject.org-hetzner-
 nbg1-01.torproject.org{139} established with SPIs cf59efd5_i c0bc9534_o
 and TS 95.216.141.241/32 2a01:4f9:c010:5f1::1/128 === 195.201.139.202/32
 2a01:4f8:c2c:1e17::1/128
 Oct  2 19:03:41 hetzner-hel1-01/hetzner-hel1-01 icinga[1469]: HOST ALERT:
 hetzner-nbg1-01;UP;SOFT;4;PING OK - Packet loss = 0%, RTA = 26.98 ms
 }}}

 A similar problem occured when macrum rebooted. From nbg's point of view,
 it went down, for sure, but then it took forever to rekey, as it was stuck
 in this state:

 {{{
 hetzner-nbg1-01.torproject.org-macrum.torproject.org[50]: ESTABLISHED 47
 minutes ago,
 195.201.139.202[195.201.139.202]...138.201.192.11[138.201.192.11]
 hetzner-nbg1-01.torproject.org-macrum.torproject.org[50]: IKEv2 SPIs:
 c1869d7083d456cd_i adcdb88009c5736e_r*, pre-shared key reauthentication in
 117 minutes
 hetzner-nbg1-01.torproject.org-macrum.torproject.org[50]: IKE proposal:
 AES_CBC_128/HMAC_SHA2_256_128/PRF_HMAC_SHA2_256/MODP_3072
 hetzner-nbg1-01.torproject.org-macrum.torproject.org[50]: Tasks queued:
 CHILD_REKEY
 hetzner-nbg1-01.torproject.org-macrum.torproject.org[50]: Tasks active:
 CHILD_REKEY
 hetzner-nbg1-01.torproject.org-macrum.torproject.org{152}:  REKEYING,
 TUNNEL, reqid 2, expires in 12 minutes
 hetzner-nbg1-01.torproject.org-macrum.torproject.org{152}:
 195.201.139.202/32 2a01:4f8:c2c:1e17::1/128 === 138.201.192.11/32
 138.201.212.224/28 172.30.133.0/24 2a01:4f8:172:39ca::2/128
 2a01:4f8:172:39ca:0:dad3::/96
 }}}

 At that point, the tunnel had already been down for a while - macrum was
 rebooted at 19:04 - but it took a full 20 minutes for ipsec to recover:

 {{{
 Oct  2 19:18:45 hetzner-nbg1-01/hetzner-nbg1-01 charon[963]: 16[IKE]
 establishing CHILD_SA hetzner-nbg1-01.torproject.org-
 macrum.torproject.org{2}
 Oct  2 19:21:30 hetzner-nbg1-01/hetzner-nbg1-01 charon[963]: 14[IKE]
 initiating IKE_SA hetzner-nbg1-01.torproject.org-macrum.torproject.org[55]
 to 138.201.192.11
 Oct  2 19:21:30 hetzner-nbg1-01/hetzner-nbg1-01 charon[963]: 12[IKE]
 establishing CHILD_SA hetzner-nbg1-01.torproject.org-
 macrum.torproject.org{2}
 Oct  2 19:21:30 hetzner-nbg1-01/hetzner-nbg1-01 charon[963]: 10[IKE]
 IKE_SA hetzner-nbg1-01.torproject.org-macrum.torproject.org[55]
 established between
 195.201.139.202[195.201.139.202]...138.201.192.11[138.201.192.11]
 Oct  2 19:21:30 hetzner-nbg1-01/hetzner-nbg1-01 charon[963]: 10[IKE]
 CHILD_SA hetzner-nbg1-01.torproject.org-macrum.torproject.org{166}
 established with SPIs cfe1be1c_i c2ce0e71_o and TS 195.201.139.202/32
 2a01:4f8:c2c:1e17::1/128 === 138.201.192.11/32 138.201.212.224/28
 172.30.133.0/24 2a01:4f8:172:39ca::2/128 2a01:4f8:172:39ca:0:dad3::/96
 }}}

 in comparison, nagios barely flinched when the server went down:

 {{{
 Oct  2 19:04:00 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 15[IKE]
 deleting IKE_SA hetzner-hel1-01.torproject.org-macrum.torproject.org[31]
 between 95.216.141.241[95.216.141.241]...138.201.192.11[138.201.192.11]
 Oct  2 19:04:00 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 05[IKE]
 initiating IKE_SA hetzner-hel1-01.torproject.org-macrum.torproject.org[46]
 to 138.201.192.11
 Oct  2 19:04:31 hetzner-hel1-01/hetzner-hel1-01 icinga[1469]: HOST ALERT:
 macrum;DOWN;SOFT;1;PING CRITICAL - Packet loss = 100%
 Oct  2 19:05:21 hetzner-hel1-01/hetzner-hel1-01 icinga[1469]: SERVICE
 ALERT: macrum;unwanted process - postgrey;CRITICAL;HARD;1;CHECK_NRPE STATE
 CRITICAL: Socket timeout after 50 seconds.
 Oct  2 19:05:21 hetzner-hel1-01/hetzner-hel1-01 icinga[1469]: SERVICE
 ALERT: macrum;SSL cert - host;CRITICAL;HARD;1;CHECK_NRPE STATE CRITICAL:
 Socket timeout after 50 seconds.
 Oct  2 19:05:30 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 15[IKE]
 establishing CHILD_SA hetzner-hel1-01.torproject.org-
 macrum.torproject.org{2}
 Oct  2 19:05:30 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 06[IKE]
 IKE_SA hetzner-hel1-01.torproject.org-macrum.torproject.org[46]
 established between
 95.216.141.241[95.216.141.241]...138.201.192.11[138.201.192.11]
 Oct  2 19:05:30 hetzner-hel1-01/hetzner-hel1-01 charon[917]: 06[IKE]
 CHILD_SA hetzner-hel1-01.torproject.org-macrum.torproject.org{140}
 established with SPIs c93eb90f_i c8942f69_o and TS 95.216.141.241/32
 2a01:4f9:c010:5f1::1/128 === 138.201.192.11/32 138.201.212.224/28
 172.30.133.0/24 2a01:4f8:172:39ca::2/128 2a01:4f8:172:39ca:0:dad3::/96
 Oct  2 19:05:41 hetzner-hel1-01/hetzner-hel1-01 icinga[1469]: HOST ALERT:
 macrum;UP;SOFT;2;PING OK - Packet loss = 0%, RTA = 25.46 ms
 }}}

 19:04:00 is (basically) when macrum went down (syslog stopped writing at
 19:03:59), and it brought back up its strongswan service at 19:05:26, so
 it took less than 5 seconds for nagios to reconnect.

 so there's definitely something wrong with strongswan on that prometheus
 server. i've closed the ticket with hetzner as it now seems obvious they
 are not the cause of this problem.

--
Ticket URL: <https://trac.torproject.org/projects/tor/ticket/31916#comment:4>
Tor Bug Tracker & Wiki <https://trac.torproject.org/>
The Tor Project: anonymity online

_______________________________________________
tor-bugs mailing list
tor-bugs@xxxxxxxxxxxxxxxxxxxx
https://lists.torproject.org/cgi-bin/mailman/listinfo/tor-bugs

References:
- [tor-bugs] #31916 [Internal Services/Tor Sysadmin Team]: reliability issues with hetzner-nbg1-01
  - From: Tor Bug Tracker & Wiki

Prev by Author: [tor-bugs] #32035 [Circumvention/BridgeDB]: Only use translations that are >=80% complete
Next by Author: Re: [tor-bugs] #32258 [Applications/Tor Browser]: Auto-Update to most recent Tor-Browser: Message about profile not readable, all windows black afterwards
Previous by thread: Re: [tor-bugs] #31916 [Internal Services/Tor Sysadmin Team]: reliability issues with hetzner-nbg1-01
Next by thread: Re: [tor-bugs] #31916 [Internal Services/Tor Sysadmin Team]: reliability issues with hetzner-nbg1-01
Index(es):
- Author
- Thread