I had some more time to look into this.  I've upgraded several
machines to more recent snapshots (which includes rzalamena's commit
to util.c and reyk's commit to log.c) but still see this.  It happens
on 'real' amd64 machines, KVM vm's running amd64 and an i386 machine
too.

I've now ktraced with -i next to -d (-i was missing previously, so the
traces weren't very useful - apologies).  The ktrace and kdump output
are rather large (60.2M for the ktrace, 58.5M for the kdump) for the
i386 machine that was first to hit it again after running under
ktrace, so I'm not attaching those (happy to make those available on
request).

I was looking for "exit" in the kdump output and I see regularly
occuring exits (from what looks like the constraint process).
However, at some point there's this (kdump | cat -n):

1125061  87570 ntpd     CALL  socket(AF_INET,0x1<SOCK_STREAM>,0x6)
1125062  87570 ntpd     RET   socket 4
1125063  87570 ntpd     CALL  kbind(0xcf7f0248,12,0x5fdcc0e48ad4ad53)
1125064  87570 ntpd     RET   kbind 0
1125065  87570 ntpd     CALL  connect(4,0x809207e0,16)
1125066  87570 ntpd     STRU  struct sockaddr { AF_INET, 199.16.156.102:443 }
1125067  16298 ntpd     PSIG  SIGTERM SIG_DFL
1125068  83655 ntpd     STRU  struct pollfd [4] { fd=3, events=0x1<POLLIN>, 
revents=0<> } { fd=4, events=0x1<POLLIN>, revents=0<> } { fd=5, 
events=0x1<POLLIN>, revents=0<> } { fd=17, events=0x1<POLLIN>, revents=0<> }
1125069  83655 ntpd     PSIG  SIGTERM caught handler=0x165af6e0 mask=0<>
1125070  83655 ntpd     RET   poll -1 errno 4 Interrupted system call
1125071  83655 ntpd     CALL  sigreturn(0xcf7cdf6c)
1125072  83655 ntpd     RET   sigreturn JUSTRETURN
1125073  83655 ntpd     CALL  sendmsg(3,0xcf7ce23c,0)
1125074  83655 ntpd     STRU  struct msghdr { name=0x0, namelen=0, 
iov=0xcf7cc23c, iovlen=0, control=0x0, controllen=0, flags=0 }
1125075  83655 ntpd     RET   sendmsg -1 errno 32 Broken pipe
1125076  83655 ntpd     CALL  kbind(0xcf7cc1a8,12,0x2af7a8a1a984823f)
1125077  83655 ntpd     RET   kbind 0
1125078  83655 ntpd     CALL  sendmsg(4,0xcf7ce23c,0)
1125079  83655 ntpd     STRU  struct msghdr { name=0x0, namelen=0, 
iov=0xcf7cc23c, iovlen=0, control=0x0, controllen=0, flags=0 }
1125080  83655 ntpd     RET   sendmsg 0
1125081  83655 ntpd     CALL  write(2,0xcf7cdd5e,0x13)
1125082  83655 ntpd     GIO   fd 2 wrote 19 bytes
1125083        "ntp engine exiting
1125084        "

and a bit later:

1127174  87570 ntpd     CALL  munmap(0x7f568000,0x1000)
1127175  87570 ntpd     RET   munmap 0
1127176  87570 ntpd     CALL  exit(0)
1127177  38871 ntpd     RET   wait4 87570/0x15612
1127178  38871 ntpd     CALL  wait4(WAIT_ANY,0,0<>,0)
1127179  38871 ntpd     RET   wait4 -1 errno 10 No child processes
1127180  38871 ntpd     CALL  getpid()
1127181  38871 ntpd     RET   getpid 38871/0x97d7
1127182  38871 ntpd     CALL  sendsyslog(0xcf7dbaf7,28,0<>)
1127183  38871 ntpd     GIO   fd -1 wrote 28 bytes
1127184        "<30>ntpd[38871]: Terminating"
1127185  38871 ntpd     RET   sendsyslog 0
1127186  38871 ntpd     CALL  kbind(0xcf7de048,12,0xc1820ba2e9e4674a)
1127187  38871 ntpd     RET   kbind 0

and then PID 38871 also exits, and then that's that.


So, there's this pid 16298 in there that gets SIGTERM for some reason
(line 1125067).  This is also a constraint process:

1090139  16298 ntpd     NAMI  "/usr/sbin/ntpd"
1090140  16298 ntpd     ARGS
1090141         [0] = "ntpd"
1090142         [1] = "-P"
1090143         [2] = "constraint"
1090144         [3] = "-v"
1090145  16298 ntpd     NAMI  "/usr/libexec/ld.so"

Which, apart from the SIGTERM seems to behave quite like the other
constraint processes (from casual reading of the kdump output, at
least).

Any ideas what I should look for now?

Paul 'WEiRD' de Weerd

On Sun, Oct 02, 2016 at 06:37:04PM +0200, Sebastien Marie wrote:
| Hi Paul,
| 
| Just to saying that I saw this behaviour. More details below.
| 
| On Sun, Oct 02, 2016 at 06:15:42PM +0200, Paul de Weerd wrote:
| > 
| > Since upgrading several machines to a more current snapshot (in an
| > effort to keep up to date with LibreSSL fixes), I noticed ntpd started
| > failing.  Here's what I see on my laptop:
| > 
| > Oct  2 17:50:15 drop doas: weerd ran command rcctl start ntpd as root from 
/home/weerd
| > Oct  2 17:50:28 drop ntpd[17059]: Terminating
| > Oct  2 17:52:50 drop doas: weerd ran command rcctl start ntpd as root from 
/home/weerd
| > Oct  2 17:53:03 drop ntpd[27986]: Terminating
| > Oct  2 17:53:18 drop doas: weerd ran command ktrace -d ntpd -v as root from 
/home/weerd
| > Oct  2 17:53:30 drop ntpd[97855]: Terminating
| > 
| > I have ntpd_flags="-v" in my /etc/rc.conf.local, but the above is all
| > the logging output I get (that's from my *.* syslog file, that also
| > includes DEBUG output).
| 
| for me, no override of ntpd_flags.
| 
| ntpd.conf configured as:
|       servers fr.pool.ntp.org
|       constraints from www.duckduckgo.com
| 
| > So far, 5 machines have been upgraded and 4 of them show this behavior
| > (although my laptop is now really fast to exit).  These are all amd64
| > machines (because I haven't gotten around to upgrading the few i386 I
| > still have running yet).  They're 'real' and virtual (KVM) machines.
| 
| I saw it on two amd64 hosts. I have i386 hosts (but the config is
| differents: use local servers).
| 
| > Has anyone else seen this behavior?
| 
| yes.
| 
| I also tried to run with kern.nosuidcoredump=3 but the terminating don't
| generated any coredump in /var/crash/ntpd.
| 
| the process terminaison isn't automatic: my ntpd is now running fine
| since almost 1 day.
| -- 
| Sebastien Marie
| 

-- 
>++++++++[<++++++++++>-]<+++++++.>+++[<------>-]<.>+++[<+
+++++++++++>-]<.>++[<------------>-]<+.--------------.[-]
                 http://www.weirdnet.nl/                 

Reply via email to