Infrastructure » sepia

I think we should add 'clock' to internal tasks by default rather than 'clock.check'. This will make it stop ntpd, run ntpdate, and restart ntp, which gives a better chance of handling wrong times (ntpd takes minutes to settle). Testing that idea now.

http://pulpito.ceph.com/dmick-2017-01-13_14:55:52-rados-master---basic-smithi/

Hrm, it was the fucking leap second.

Mar  1 00:12:50 smithi181 ntpd[1814]: kernel reports leap second has occurred
Mar  1 00:12:50 smithi181 ntpd[1814]: kernel reports leap second has occurred

okay, here is run /a/sage-2017-02-24_06:15:05-rados-wip-sage-testing---basic-smithi/855210

2017-02-24T07:32:31.781 INFO:tasks.ceph.mon.b.smithi191.stdout:starting mon.b rank 1 at 172.21.15.191:6789/0 mon_data /var/lib/ceph/mon/ceph-b fsid b0586099-a577-49e3-a180-bc6dcfce0c8c
2017-02-24T07:32:31.913 INFO:tasks.ceph.mon.a.smithi006.stdout:starting mon.a rank 0 at 172.21.15.6:6789/0 mon_data /var/lib/ceph/mon/ceph-a fsid b0586099-a577-49e3-a180-bc6dcfce0c8c
2017-02-24T07:32:31.937 INFO:tasks.ceph.mon.c.smithi006.stdout:starting mon.c rank 2 at 172.21.15.6:6790/0 mon_data /var/lib/ceph/mon/ceph-c fsid b0586099-a577-49e3-a180-bc6dcfce0c8c

remote/smithi191/log/ceph-mon.b.log:2017-02-24 07:32:31.785947 7f54ca7de880  0 starting mon.b rank 1 at 172.21.15.191:6789/0 mon_data /var/lib/ceph/mon/ceph-b fsid b0586099-a577-49e3-a180-bc6dcfce0c8c
remote/smithi006/log/ceph-mon.a.log:2017-02-24 07:32:41.327674 7f7a5eb09800  0 starting mon.a rank 0 at 172.21.15.6:6789/0 mon_data /var/lib/ceph/mon/ceph-a fsid b0586099-a577-49e3-a180-bc6dcfce0c8c
remote/smithi006/log/ceph-mon.c.log:2017-02-24 07:32:41.352288 7f4a114f3800  0 starting mon.c rank 2 at 172.21.15.6:6790/0 mon_data /var/lib/ceph/mon/ceph-c fsid b0586099-a577-49e3-a180-bc6dcfce0c8c

syslog only shows

Feb 24 07:30:48 smithi006 python: ansible-systemd Invoked with name=ntpd enabled=True daemon_reload=False state=started user=False masked=None

2017-02-24T07:30:38.956 INFO:teuthology.task.ansible.out:ok: [smithi006.front.sepia.ceph.com] => {"changed": false, "enabled": true, "name": "ntpd", "state": "started", "status": {"ActiveEnterTimestamp": "Fri 2017-02-24 04:41:52 UTC", "ActiveEnterTimestampMonotonic": "253965470", "ActiveExitTimestampMonotonic": "0", "ActiveState": "active", "After": "tmp.mount ntpdate.service syslog.target systemd-journald.socket sntp.service system.slice -.mount basic.target", "AllowIsolate": "no", "AssertResult": "yes", "AssertTimestamp": "Fri 2017-02-24 04:41:52 UTC", "AssertTimestampMonotonic": "253900537", "Before": "shutdown.target multi-user.target chronyd.service", "BlockIOAccounting": "no", "BlockIOWeight": "18446744073709551615", "CPUAccounting": "no", "CPUQuotaPerSecUSec": "infinity", "CPUSchedulingPolicy": "0", "CPUSchedulingPriority": "0", "CPUSchedulingResetOnFork": "no", "CPUShares": "18446744073709551615", "CanIsolate": "no", "CanReload": "no", "CanStart": "yes", "CanStop": "yes", "CapabilityBoundingSet": "18446744073709551615", "ConditionResult": "yes", "ConditionTimestamp": "Fri 2017-02-24 04:41:52 UTC", "ConditionTimestampMonotonic": "253900537", "ConflictedBy": "chronyd.service", "Conflicts": "shutdown.target", "ControlGroup": "/system.slice/ntpd.service", "ControlPID": "0", "DefaultDependencies": "yes", "Delegate": "no", "Description": "Network Time Service", "DevicePolicy": "auto", "EnvironmentFile": "/etc/sysconfig/ntpd (ignore_errors=yes)", "ExecMainCode": "0", "ExecMainExitTimestampMonotonic": "0", "ExecMainPID": "18730", "ExecMainStartTimestamp": "Fri 2017-02-24 04:41:52 UTC", "ExecMainStartTimestampMonotonic": "253965414", "ExecMainStatus": "0", "ExecStart": "{ path=/usr/sbin/ntpd ; argv[]=/usr/sbin/ntpd -u ntp:ntp $OPTIONS ; ignore_errors=no ; start_time=[n/a] ; stop_time=[n/a] ; pid=0 ; code=(null) ; status=0/0 }", "FailureAction": "none", "FileDescriptorStoreMax": "0", "FragmentPath": "/usr/lib/systemd/system/ntpd.service", "GuessMainPID": "yes", "IOScheduling": "0", "Id": "ntpd.service", "IgnoreOnIsolate": " 
2017-02-24T07:30:38.958 INFO:teuthology.task.ansible.out:no", "IgnoreOnSnapshot": "no", "IgnoreSIGPIPE": "yes", "InactiveEnterTimestampMonotonic": "0", "InactiveExitTimestamp": "Fri 2017-02-24 04:41:52 UTC", "InactiveExitTimestampMonotonic": "253913420", "JobTimeoutAction": "none", "JobTimeoutUSec": "0", "KillMode": "control-group", "KillSignal": "15", "LimitAS": "18446744073709551615", "LimitCORE": "18446744073709551615", "LimitCPU": "18446744073709551615", "LimitDATA": "18446744073709551615", "LimitFSIZE": "18446744073709551615", "LimitLOCKS": "18446744073709551615", "LimitMEMLOCK": "65536", "LimitMSGQUEUE": "819200", "LimitNICE": "0", "LimitNOFILE": "4096", "LimitNPROC": "127553", "LimitRSS": "18446744073709551615", "LimitRTPRIO": "0", "LimitRTTIME": "18446744073709551615", "LimitSIGPENDING": "127553", "LimitSTACK": "18446744073709551615", "LoadState": "loaded", "MainPID": "18730", "MemoryAccounting": "no", "MemoryCurrent": "18446744073709551615", "MemoryLimit": "18446744073709551615", "MountFlags": "0", "Names": "ntpd.service", "NeedDaemonReload": "no", "Nice": "0", "NoNewPrivileges": "no", "NonBlocking": "no", "NotifyAccess": "none", "OOMScoreAdjust": "0", "OnFailureJobMode": "replace", "PermissionsStartOnly": "no", "PrivateDevices": "no", "PrivateNetwork": "no", "PrivateTmp": "yes", "ProtectHome": "no", "ProtectSystem": "no", "RefuseManualStart": "no", "RefuseManualStop": "no", "RemainAfterExit": "no", "Requires": "basic.target -.mount", "RequiresMountsFor": "/var/tmp", "Restart": "no", "RestartUSec": "100ms", "Result": "success", "RootDirectoryStartOnly": "no", "RuntimeDirectoryMode": "0755", "SameProcessGroup": "no", "SecureBits": "0", "SendSIGHUP": "no", "SendSIGKILL": "yes", "Slice": "system.slice", "StandardError": "inherit", "StandardInput": "null", "StandardOutput": "journal", "StartLimitAction": "none", "StartLimitBurst": "5", "StartLimitInterval": "10000000", "StartupBlockIOWeight": "18446744073709551615", "StartupCPUShares": "18446744073709551615", "StatusErrno": "0", "StopWhenUnneeded": "no", "SubState": 
2017-02-24T07:30:38.960 INFO:teuthology.task.ansible.out:"running", "SyslogLevelPrefix": "yes", "SyslogPriority": "30", "SystemCallErrorNumber": "0", "TTYReset": "no", "TTYVHangup": "no", "TTYVTDisallocate": "no", "TimeoutStartUSec": "1min 30s", "TimeoutStopUSec": "1min 30s", "TimerSlackNSec": "50000", "Transient": "no", "Type": "forking", "UMask": "0022", "UnitFilePreset": "disabled", "UnitFileState": "enabled", "WantedBy": "multi-user.target", "Wants": "system.slice", "WatchdogTimestamp": "Fri 2017-02-24 04:41:52 UTC", "WatchdogTimestampMonotonic": "253965428", "WatchdogUSec": "0"}, "warnings": []}

but a few seconds later,

2017-02-24T07:30:43.072 INFO:teuthology.orchestra.run.smithi006:Running: 'sudo service ntp stop ; sudo ntpdate 0.us.pool.ntp.org 1.us.pool.ntp.org 2.us.pool.ntp.org 3.us.pool.ntp.org ; sudo service ntp start ; PATH=/usr/bin:/usr/sbin ntpdc -p'
2017-02-24T07:30:43.165 INFO:teuthology.orchestra.run.smithi006.stderr:Redirecting to /bin/systemctl stop  ntp.service
2017-02-24T07:30:43.174 INFO:teuthology.orchestra.run.smithi006.stderr:Failed to stop ntp.service: Unit ntp.service not loaded.
2017-02-24T07:30:43.187 INFO:teuthology.orchestra.run.smithi006.stderr:24 Feb 07:30:52 ntpdate[5001]: the NTP socket is in use, exiting
2017-02-24T07:30:43.206 INFO:teuthology.orchestra.run.smithi006.stderr:Redirecting to /bin/systemctl start  ntp.service
2017-02-24T07:30:43.209 INFO:teuthology.orchestra.run.smithi006.stderr:Failed to start ntp.service: Unit not found.
2017-02-24T07:30:43.214 INFO:teuthology.orchestra.run.smithi006.stdout:     remote           local      st poll reach  delay   offset    disp
2017-02-24T07:30:43.215 INFO:teuthology.orchestra.run.smithi006.stdout:=======================================================================
2017-02-24T07:30:43.215 INFO:teuthology.orchestra.run.smithi006.stdout:*level1g.cs.unc. 172.21.15.6      1 1024  377 0.01782  0.000345 0.10847
2017-02-24T07:30:43.215 INFO:teuthology.orchestra.run.smithi006.stdout:=clock.trit.net  172.21.15.6      2 1024  377 0.06496 -9.418840 0.08762
2017-02-24T07:30:43.215 INFO:teuthology.orchestra.run.smithi006.stdout:=74.120.81.219   172.21.15.6      2  512  374 0.04167 -0.000045 0.12901
2017-02-24T07:30:43.217 INFO:teuthology.orchestra.run.smithi006.stdout:=services.quadra 172.21.15.6      3  512  277 0.06560 -0.004937 0.11520
2017-02-24T07:30:43.226 DEBUG:teuthology.orchestra.remote:smithi191:/etc/ntp.conf is 3KB
2017-02-24T07:30:43.276 INFO:teuthology.orchestra.run.smithi191:Running: 'sudo service ntp stop ; sudo ntpdate 0.us.pool.ntp.org 1.us.pool.ntp.org 2.us.pool.ntp.org 3.us.pool.ntp.org ; sudo service ntp start ; PATH=/usr/bin:/usr/sbin ntpdc -p'
2017-02-24T07:30:45.989 INFO:teuthology.orchestra.run.smithi191.stderr:24 Feb 07:30:46 ntpdate[158412]: 108.61.56.35 rate limit response from server.
2017-02-24T07:30:46.045 INFO:teuthology.orchestra.run.smithi191.stderr:24 Feb 07:30:46 ntpdate[158412]: 138.68.46.177 rate limit response from server.
2017-02-24T07:30:46.637 INFO:teuthology.orchestra.run.smithi191.stderr:24 Feb 07:30:46 ntpdate[158412]: 198.55.111.50 rate limit response from server.
2017-02-24T07:30:54.569 INFO:teuthology.orchestra.run.smithi191.stdout:24 Feb 07:30:54 ntpdate[158412]: adjust time server 132.163.4.102 offset -0.008426 sec
2017-02-24T07:30:54.739 INFO:teuthology.orchestra.run.smithi191.stderr:ntpdc: read: Connection refused

so... maybe the problem is that we're getting rate limited? in which case, maybe we need our own ntp pool?