Re: RLIMIT_CPU doesn't work reliably on mostly idle systems

[Scott Cheloha]

On Tue, Aug 29, 2023 at 07:15:14PM +0200, Claudio Jeker wrote:
> On Tue, Aug 29, 2023 at 01:01:10AM +, Eric Wong wrote:
> > >Synopsis: RLIMIT_CPU doesn't work reliably on mostly idle systems
> > >Category: system
> > >Environment:
> > System  : OpenBSD 7.3
> > Details : OpenBSD 7.3 (GENERIC.MP) #1242: Sat Mar 25 18:04:31 MDT 
> > 2023
> >  
> > dera...@octeon.openbsd.org:/usr/src/sys/arch/octeon/compile/GENERIC.MP
> > 
> > Architecture: OpenBSD.octeon
> > Machine : octeon
> > >Description:
> > 
> > RLIMIT_CPU doesn't work reliably when few/no syscalls are made on an
> > otherwise idle system (aside from the test process using up CPU).
> > It can take 20-50s to fire SIGKILL with rlim_max=9 (and the SIGXCPU
> > from rlim_cur=1 won't even fire).
> > 
> > I can reproduce this on a private amd64 VM and also on gcc231
> > on GCC compiler farm .
> > I can't reproduce this on a busy system like gcc220 on cfarm,
> > however.
> 
> Thanks for the report. There is indeed an issue in how the CPU time is
> accounted on an idle system. The below diff is a possible fix.
> 
> In roundrobin() force a resched and therefor mi_switch() when
> SPCF_SHOULDYIELD is set. On an idle CPU mi_switch() will just do all
> accounting bits but skip the expensive cpu_switchto() since the proc
> remains the same.

This is an elegant solution.  I'm a little reluctant to add
mi_switch() overhead to a thread if *nothing* else wants to run, but
the roundrobin() quantum is massive at the moment, so it's not all
that much.  This change also fixes a couple other things.

- Runaway user threads (like a synthetic spinloop) can no longer
  keep the system from suspending.  If such threads are forced into
  mi_switch() after two ticks, sched_chooseproc() will then see
  SPCF_SHOULDHALT, etc.

- Sibling theads in a process using ITIMER_VIRTUAL or ITIMER_PROF
  are now forced to enable the itimer_update() interrupt after
  two ticks.

- Sibling threads in a process running profil(2) are now forced
  to enable the profclock() interrupt after two ticks.

For sake of discussion, an alternative approach is below.  Basically,
tweak rucheck() to account for any un-accumulated ONPROC time.  It
seems to work.

I would lean toward your change, though.  Fixing those other things is
a nice bonus.

Index: kern_resource.c
===
RCS file: /cvs/src/sys/kern/kern_resource.c,v
retrieving revision 1.78
diff -u -p -r1.78 kern_resource.c
--- kern_resource.c 29 Aug 2023 16:19:34 -  1.78
+++ kern_resource.c 29 Aug 2023 22:21:06 -
@@ -531,21 +531,32 @@ ruadd(struct rusage *ru, struct rusage *
 void
 rucheck(void *arg)
 {
+   struct timespec elapsed, now, total;
struct rlimit rlim;
struct process *pr = arg;
time_t runtime;
+   struct proc *p;
int s;
 
KERNEL_ASSERT_LOCKED();
 
SCHED_LOCK(s);
-   runtime = pr->ps_tu.tu_runtime.tv_sec;
+   nanouptime();
+   total = pr->ps_tu.tu_runtime;
+   TAILQ_FOREACH(p, >ps_threads, p_thr_link) {
+   if (p->p_stat == SONPROC) {
+   timespecsub(, >p_cpu->ci_schedstate.spc_runtime,
+   );
+   timespecadd(, , );
+   }
+   }
SCHED_UNLOCK(s);
 
mtx_enter(>ps_mtx);
rlim = pr->ps_limit->pl_rlimit[RLIMIT_CPU];
mtx_leave(>ps_mtx);
 
+   runtime = total.tv_sec;
if ((rlim_t)runtime >= rlim.rlim_cur) {
if ((rlim_t)runtime >= rlim.rlim_max) {
prsignal(pr, SIGKILL);

Re: RLIMIT_CPU doesn't work reliably on mostly idle systems

[Scott Cheloha]

> On Aug 28, 2023, at 20:04, Eric Wong  wrote:
> 
> 
>> 
>> Synopsis: RLIMIT_CPU doesn't work reliably on mostly idle systems
>> Category: system
>> Environment:
>System  : OpenBSD 7.3
>Details : OpenBSD 7.3 (GENERIC.MP) #1242: Sat Mar 25 18:04:31 MDT 2023
> 
> dera...@octeon.openbsd.org:/usr/src/sys/arch/octeon/compile/GENERIC.MP
> 
>Architecture: OpenBSD.octeon
>Machine : octeon
>> Description:
> 
> RLIMIT_CPU doesn't work reliably when few/no syscalls are made on an
> otherwise idle system (aside from the test process using up CPU).
> It can take 20-50s to fire SIGKILL with rlim_max=9 (and the SIGXCPU
> from rlim_cur=1 won't even fire).
> 
> I can reproduce this on a private amd64 VM and also on gcc231
> on GCC compiler farm .
> I can't reproduce this on a busy system like gcc220 on cfarm,
> however.
> 
>> How-To-Repeat:
> 
> Following is a standalone C program which demonstrates the problem on
> a mostly idle system:
> /*
> * Most reliably reproduced with compiler optimizations disabled:
> *
> *   cc -o rlimit_cpu -ggdb3 -Wall rlimit_cpu.c
> *
> * Neither SIGXCPU (from rlim_cur) nor SIGKILL (from rlim_max)
> * with RLIMIT_CPU set seem to fire reliably with few syscalls being made.
> * On an otherwise idle system, it can take many more seconds (20-50s)
> * than expected when rlim_max=9 (SIGXCPU doesn't even happen).
> * Best case is 2 seconds for SIGXCPU when rlim_cur=1 on a busy system
> * which is understandable due to kernel accounting delays.
> *
> * I rely on RLIMIT_CPU to protect systems from pathological userspace
> * code (diff generation, regexps, etc)
> *
> * Testing on cfarm  machines,
> * the issue is visible on a mostly-idle 4-core gcc231 mips64
> * but doesn't seem to happen on the busy 12-core gcc220 machine
> * (only 2 seconds for XCPU w/ rlim_cur=1)
> */
> #include 
> #include 
> #include 
> #include 
> 
> static void sigxcpu(int sig)
> {
>write(1, "SIGXCPU\n", 8);
>_exit(1);
> }
> 
> static volatile size_t nr; // volatile to disable optimizations
> int main(void)
> {
>struct rlimit rlim = { .rlim_cur = 1, .rlim_max = 9 };
>int rc;
> 
>signal(SIGXCPU, sigxcpu);
>rc = setrlimit(RLIMIT_CPU, );
>assert(rc == 0);
> 
>/*
> * adding some time, times, and write syscalls improve likelyhood of
> * of rlimit signals firing in a timely manner.  writes to /dev/null
> * seems less-likely to trigger than writes to the terminal or
> * regular file.
> */
>for (;; nr++) {
>}
> 
>return 0;
> }
> 
>> Fix:
>Making more syscalls can workaround the problem, but that's not
> an option when dealing with userspace-heavy code like pathological regexps.

The CPU time limit is checked from a
periodic timeout.

CPU time totals accumulate in mi_switch().

The problem is that on a mostly idle system,
a user thread that is hogging the CPU may
take a very long time to switch out, and the
and all that CPU time doesn't accumulate
until the switch, and so the signal will
arrive later than requested.

System calls have points where a thread can
switch out, which is why the delay is
exaggerated on synthetic workloads like the
busy-loop shown above.

One possible solution is to check usage
times for threads that are still ONPROC
during the rusage timeout.

Another approach is to be more aggressive
about forcing threads to switch out, even
when nothing else wants to run.

Coincidentally, we are discussing p_rtime on
tech@ right now, which is tangentially related
to this issue.

Re: resistance against single-even upsets

[Scott Cheloha]

> On Mar 14, 2023, at 11:32 AM, p...@delphinusdns.org wrote:
> 
>> Synopsis: can we resist agains bit flipping?
>> Category: system
>> Environment:
> System  : OpenBSD 7.2
> Details : OpenBSD 7.2 (GENERIC.MP) #2: Thu Nov 24 23:53:03 MST 2022
> r...@syspatch-72-arm64.openbsd.org:/usr/src/sys/arch/arm64/compile/GENERIC.MP
> 
> Architecture: OpenBSD.arm64
> Machine : arm64
>> Description:
> https://en.wikipedia.org/wiki/Single-event_upset
> 
> A single event upset gave someone in belgium who was in a poll, 4096
> extra votes.  When I think about this bit flip and look at the kernel
> code for an ultra secure operating system there is not much stopping
> someone to try an attack during a cosmic storm or increased solar
> activity.  Perhaps a bit flips somewhere in the CPU or RAM?
> 
> pjp@polarstern$ grep sourceroute ip_input.c
> int ip_dosourceroute = 0;
>if (!ip_dosourceroute) {
>if (!ip_dosourceroute)
>_dosourceroute);
> 
> Like here.  As you know someone found something last week if this were
> enabled.  But the way this check is.  It doesn't check for the low bit set to
> one but it checks for the inverted value, so if the 12th bit was flipped in a
> solar storm ip_dosourceroute would now be 4096.  And the system would be wide
> open.
> 
>> How-To-Repeat:
> Hackers probably check the weather report like 
> https://spaceweather.com/ for increased solar activity and then fill
> the CPU caches with attempts to get a bit flip happening.  The odds
> aren't in their favour but who knows they may get lucky. 
>> Fix:
> I propose all these variables to be monitored occasionally with a CRC
> check and if there is a bit flip happening to unset it to the right value.
> This is a lot of work but may be worth it.  OpenBSD would never be faring to
> space right?  I have no code but trying to think around how to do this.

Why wouldn't you just buy ECC memory?

https://en.wikipedia.org/wiki/ECC_memory

Re: panic at reboot - tsc_test_sync_ap

[Scott Cheloha]

Pedro,

On Wed, Dec 14, 2022 at 12:24:42PM -0600, Scott Cheloha wrote:
> On Wed, Dec 14, 2022 at 11:37:14AM +, Pedro Caetano wrote:
> > Hi bugs@
> > 
> > In the process of upgrading a pair of servers to release 7.2, the following
> > panic was triggered after sysupgrade reboot. (dell poweredge R740)
> > 
> > One of the reboots happened before syspatch, the other happened after
> > applying the release patches.
> > 
> > After powercycling, both servers managed to boot successfully.
> > 
> > Please keep me copied as I'm not subscribed to bugs@
> > 
> > 
> > Screenshot of the panic uploaded attached to this email.
> 
> For reference:
> 
> cpu2: 32KB 64B/line 8-way D-cache, 32KB 64b/line 8-way I-cache, 1MB 64b/line 
> 16-way L2 cache, 8MB 64b/line 11-way L3 cache
> cpu2: smt 0, core 5, package 0
> panic: tsc_test_sync_ap: cpu2: tsc_ap_name is not NULL: cpu1
> panic: tsc_test_sync_ap: cpu2: tsc_ap_name is not NULL: cpu1cpu3 at mainbus0: 
> apid 26 (application process
> 
> Somehow your machine is violating one of the TSC sync test sanity
> checks.  The idea behind this one is that there should only be one AP
> in the sync test at a time.
> 
> At the start of each test, in tsc_test_sync_ap(), the AP sets
> tsc_ap_name to its dv_xname.  It does this with an atomic CAS
> expecting NULL to ensure no other AP is still running the sync test.
> You're hitting this panic:
> 
>449  void
>450  tsc_test_sync_ap(struct cpu_info *ci)
>451  {
>452  if (!tsc_is_invariant)
>453  return;
>454  #ifndef TSC_DEBUG
>455  if (!tsc_is_synchronized)
>456  return;
>457  #endif
>458  /* The BP needs our name in order to report any problems. */
>459  if (atomic_cas_ptr(_ap_name, NULL, ci->ci_dev->dv_xname) 
> != NULL) {
>460  panic("%s: %s: tsc_ap_name is not NULL: %s",
>461  __func__, ci->ci_dev->dv_xname, tsc_ap_name);
>462  }
> 
> The BP is supposed to reset tsc_ap_name to NULL at the conclusion of
> every sync test, from tsc_test_sync_bp():
> 
>415  /*
>416   * Report what happened.  Adjust the TSC's quality
>417   * if this is the first time we've failed the test.
>418   */
>419  tsc_report_test_results();
>420  if (tsc_ap_status.lag_count || 
> tsc_bp_status.lag_count) {
>421  if (tsc_is_synchronized) {
>422  tsc_is_synchronized = 0;
>423  tc_reset_quality(_timecounter, 
> -1000);
>424  }
>425  tsc_test_rounds = 0;
>426  } else
>427  tsc_test_rounds--;
>428
>429  /*
>430   * Clean up for the next round.  It is safe to reset 
> the
>431   * ingress barrier because at this point we know the 
> AP
>432   * has reached the egress barrier.
>433   */
>434  memset(_ap_status, 0, sizeof tsc_ap_status);
>435  memset(_bp_status, 0, sizeof tsc_bp_status);
>436  tsc_ingress_barrier = 0;
>437  if (tsc_test_rounds == 0)
>438  tsc_ap_name = NULL;
> 
> It's possible the BP's store:
> 
>   tsc_ap_name = NULL;
> 
> is not *always* globally visible by the time the next AP reaches the
> tsc_ap_name CAS, triggering the panic.  If so, we could force the
> store to complete with membar_producer().  tsc_ap_name should be
> volatile, too.
> 
> OTOH, it's possible this particular check is not the right thing here.
> My intention is correct... we definitely don't want more than one AP
> in the sync test at any given moment.  But this tsc_ap_name handshake
> thing may be the wrong way to assert that.

Just following up on this.  Have you seen the panic you reported again?

Re: panic at reboot - tsc_test_sync_ap

[Scott Cheloha]

On Wed, Dec 14, 2022 at 11:37:14AM +, Pedro Caetano wrote:
> Hi bugs@
> 
> In the process of upgrading a pair of servers to release 7.2, the following
> panic was triggered after sysupgrade reboot. (dell poweredge R740)
> 
> One of the reboots happened before syspatch, the other happened after
> applying the release patches.
> 
> After powercycling, both servers managed to boot successfully.
> 
> Please keep me copied as I'm not subscribed to bugs@
> 
> 
> Screenshot of the panic uploaded attached to this email.

For reference:

cpu2: 32KB 64B/line 8-way D-cache, 32KB 64b/line 8-way I-cache, 1MB 64b/line 
16-way L2 cache, 8MB 64b/line 11-way L3 cache
cpu2: smt 0, core 5, package 0
panic: tsc_test_sync_ap: cpu2: tsc_ap_name is not NULL: cpu1
panic: tsc_test_sync_ap: cpu2: tsc_ap_name is not NULL: cpu1cpu3 at mainbus0: 
apid 26 (application process

Somehow your machine is violating one of the TSC sync test sanity
checks.  The idea behind this one is that there should only be one AP
in the sync test at a time.

At the start of each test, in tsc_test_sync_ap(), the AP sets
tsc_ap_name to its dv_xname.  It does this with an atomic CAS
expecting NULL to ensure no other AP is still running the sync test.
You're hitting this panic:

   449  void
   450  tsc_test_sync_ap(struct cpu_info *ci)
   451  {
   452  if (!tsc_is_invariant)
   453  return;
   454  #ifndef TSC_DEBUG
   455  if (!tsc_is_synchronized)
   456  return;
   457  #endif
   458  /* The BP needs our name in order to report any problems. */
   459  if (atomic_cas_ptr(_ap_name, NULL, ci->ci_dev->dv_xname) != 
NULL) {
   460  panic("%s: %s: tsc_ap_name is not NULL: %s",
   461  __func__, ci->ci_dev->dv_xname, tsc_ap_name);
   462  }

The BP is supposed to reset tsc_ap_name to NULL at the conclusion of
every sync test, from tsc_test_sync_bp():

   415  /*
   416   * Report what happened.  Adjust the TSC's quality
   417   * if this is the first time we've failed the test.
   418   */
   419  tsc_report_test_results();
   420  if (tsc_ap_status.lag_count || tsc_bp_status.lag_count) 
{
   421  if (tsc_is_synchronized) {
   422  tsc_is_synchronized = 0;
   423  tc_reset_quality(_timecounter, 
-1000);
   424  }
   425  tsc_test_rounds = 0;
   426  } else
   427  tsc_test_rounds--;
   428
   429  /*
   430   * Clean up for the next round.  It is safe to reset the
   431   * ingress barrier because at this point we know the AP
   432   * has reached the egress barrier.
   433   */
   434  memset(_ap_status, 0, sizeof tsc_ap_status);
   435  memset(_bp_status, 0, sizeof tsc_bp_status);
   436  tsc_ingress_barrier = 0;
   437  if (tsc_test_rounds == 0)
   438  tsc_ap_name = NULL;

It's possible the BP's store:

tsc_ap_name = NULL;

is not *always* globally visible by the time the next AP reaches the
tsc_ap_name CAS, triggering the panic.  If so, we could force the
store to complete with membar_producer().  tsc_ap_name should be
volatile, too.

OTOH, it's possible this particular check is not the right thing here.
My intention is correct... we definitely don't want more than one AP
in the sync test at any given moment.  But this tsc_ap_name handshake
thing may be the wrong way to assert that.

Index: tsc.c
===
RCS file: /cvs/src/sys/arch/amd64/amd64/tsc.c,v
retrieving revision 1.30
diff -u -p -r1.30 tsc.c
--- tsc.c   24 Oct 2022 00:56:33 -  1.30
+++ tsc.c   14 Dec 2022 18:12:54 -
@@ -372,7 +372,7 @@ struct tsc_test_status {
 struct tsc_test_status tsc_ap_status;  /* Test results from AP */
 struct tsc_test_status tsc_bp_status;  /* Test results from BP */
 uint64_t tsc_test_cycles;  /* [p] TSC cycles per test round */
-const char *tsc_ap_name;   /* [b] Name of AP running test */
+volatile const char *tsc_ap_name;  /* [b] Name of AP running test */
 volatile u_int tsc_egress_barrier; /* [a] Test end barrier */
 volatile u_int tsc_ingress_barrier;/* [a] Test start barrier */
 volatile u_int tsc_test_rounds;/* [p] Remaining test rounds */
@@ -434,8 +434,10 @@ tsc_test_sync_bp(struct cpu_info *ci)
memset(_ap_status, 0, sizeof tsc_ap_status);
memset(_bp_status, 0, sizeof tsc_bp_status);
tsc_ingress_barrier = 0;
-   if (tsc_test_rounds == 0)
+   if (tsc_test_rounds == 0) {
tsc_ap_name = 

Re: kernel protection fault during boot on vmm(4) VM running on AMD EPYC cpu with tsc_identify in trace

[Scott Cheloha]

On Mon, Oct 31, 2022 at 12:43:50PM +0100, Paul de Weerd wrote:
> Hi folks,
> 
> I just upgraded a VM on my AMD EPYC host.  I get the following
> protection fault during boot:
> 
> ddb> bo re
> rebooting...
> Using drive 0, partition 3.
> Loading..
> probing: pc0 com0 mem[638K 3838M 256M a20=on] 
> disk: hd0+
> >> OpenBSD/amd64 BOOT 3.55
> \
> com0: 115200 baud
> switching console to com0
> >> OpenBSD/amd64 BOOT 3.55
> boot> 
> NOTE: random seed is being reused.
> booting hd0a:/bsd: 15615256+3781640+298464+0+1171456 
> [1143945+128+1225080+928182]=0x170d440
> entry point at 0x81001000
> [ using 3298368 bytes of bsd ELF symbol table ]
> Copyright (c) 1982, 1986, 1989, 1991, 1993
> The Regents of the University of California.  All rights reserved.
> Copyright (c) 1995-2022 OpenBSD. All rights reserved.  https://www.OpenBSD.org
> 
> OpenBSD 7.2-current (GENERIC) #784: Fri Oct 28 21:50:59 MDT 2022
> dera...@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC
> real mem = 4278177792 (4079MB)
> avail mem = 4131221504 (3939MB)
> random: good seed from bootblocks
> mpath0 at root
> scsibus0 at mpath0: 256 targets
> mainbus0 at root
> bios0 at mainbus0: SMBIOS rev. 2.4 @ 0xf36b0 (12 entries)
> bios0: vendor SeaBIOS version "1.14.0p0-OpenBSD-vmm" date 01/01/2011
> bios0: OpenBSD VMM
> acpi at bios0 not configured
> cpu0 at mainbus0: (uniprocessor)
> kernel: protection fault trap, code=0
> Stopped at  tsc_identify+0xcd:  rdmsr
> ddb> ps
>PID TID   PPIDUID  S   FLAGS  WAIT  COMMAND
> *0   0 -1  0  7 0x10200swapper
> ddb> trace
> tsc_identify(822c7ff0,822c7ff0,68a34bffd15c67e6,822c7ff0,10,82714c10)
>  at tsc_identify+0xcd
> identifycpu(822c7ff0,822c7ff0,bca189629b3de454,8002c400,822c7ff0,8002c424)
>  at identifycpu+0x2e4
> cpu_attach(8002c300,8002c400,82714d98,8002c300,980a70616799eafd,8002c300)
>  at cpu_attach+0x16f
> config_attach(8002c300,82289250,82714d98,8138d1b0,6c550c45866795b6,82714db8)
>  at config_attach+0x1f4
> mainbus_attach(0,8002c300,0,0,819b798732a62156,0) at 
> mainbus_attach+0x151
> config_attach(0,822891a8,0,0,6c550c4586f4e2c4,0) at 
> config_attach+0x1f4
> cpu_configure(f588b7541b8b8d14,0,0,8002e000,81abb8d3,82714f00)
>  at cpu_configure+0x33
> main(0,0,0,0,0,1) at main+0x379
> end trace frame: 0x0, count: -8
> ddb> show reg
> rdi   0x822a3035cpu_vendor+0xd
> rsi   0x81f04410cmd0646_9_tim_udma+0x170f5
> rbp   0x82714c30end+0x314c30
> rbx   0x20202020
> rdx0
> rcx   0xc0010015
> rax0
> r8 0
> r9  0x40
> r10   0x2bc299b68ee7cba5
> r11   0x75a3a544d54dd7b9
> r12  0x1
> r13   0x8002c424
> r14   0x822c7ff0cpu_info_full_primary+0x1ff0
> r15   0x82714c40end+0x314c40
> rip   0x819e1f4dtsc_identify+0xcd
> cs   0x8
> rflags   0x10202__ALIGN_SIZE+0xf202
> rsp   0x82714c10end+0x314c10
> ss  0x10
> tsc_identify+0xcd:  rdmsr
> ddb> 

You get a #GP in your VM when trying to rdmsr(MSR_HWCR).  My guess is
we need to expand the MSR read bitmap for SVM.

This patch compiles, but I can't test it.  Does it fix the panic?

CC dv@ mlarkin@

Index: vmm.c
===
RCS file: /cvs/src/sys/arch/amd64/amd64/vmm.c,v
retrieving revision 1.323
diff -u -p -r1.323 vmm.c
--- vmm.c   7 Sep 2022 18:44:09 -   1.323
+++ vmm.c   31 Oct 2022 12:38:30 -
@@ -2705,6 +2705,10 @@ vcpu_reset_regs_svm(struct vcpu *vcpu, s
/* allow reading TSC */
svm_setmsrbr(vcpu, MSR_TSC);
 
+   /* allow reading HWCR and PSTATEDEF for TSC calibration */
+   svm_setmsrbr(vcpu, MSR_HWCR);
+   svm_setmsrbr(vcpu, MSR_PSTATEDEF(0));
+
/* Guest VCPU ASID */
if (vmm_alloc_vpid()) {
DPRINTF("%s: could not allocate asid\n", __func__);

Re: 7.2: tsc timecounter running too fast on ESXi 7.5

[Scott Cheloha]

On Wed, Oct 26, 2022 at 03:23:51PM +0200, Kalabic S. wrote:
> On 26/10/2022 11:33, Scott Cheloha wrote:
> > There might be a second workaround.  Kalabic mentions here in the
> > other thread about this problem:
> > 
> > https://marc.info/?l=openbsd-bugs=14949825616=2
> > 
> > ... that changing the ESXi option "Guest OS Version" from "FreeBSD
> > (32-bit)" to "FreeBSD (64-bit)" seemed to fix the problem on his
> > version of ESXi.  Does that work for you?  I don't know what the other
> > consequences of that configuration change are, but it might be worth a
> > try if you prefer to run 7.2-RELEASE or 7.2-STABLE instead of patching
> > -current.
> > 
> > Do you have VMware support?  Is there any way for you to report this
> > problem to them?  It's unlikely they explicitly support running an
> > OpenBSD guest, but it's plausible this issue could affect other
> > operating systems.  I can't imagine OpenBSD is reading the ACPI PM
> > timer differently than Linux or FreeBSD.
> > 
> 
> Maybe related or not, but there's official paper from VMware that describes
> several known timekeeping issues and how to correct or work around them:
> https://www.cse.psu.edu/~buu1/teaching/spring06/papers/vmware-timing.pdf

I did see this, thanks for posting it.  It's not immediately useful here,
though.

> Also pardon my ignorance about TSC counters and related stuff, but just
> looking at FreeBSD related code it seems to take into account the fact it is
> running as a hypervisor guest (ESXi or Xen).
> https://github.com/freebsd/freebsd-src/blob/main/sys/x86/x86/tsc.c
> 
> Is there a detail that makes a difference when different "Guest OS Version"
> is used? Note that I have no idea what is happening there.
> 
> So, just like some AMD related improvements for TSC were introduced into
> OpenBSD recently, maybe this issue can be properly solved only by doing
> something similar for guests on hypervisor?

I would like to derive the TSC and lapic frequency from the hypervisor
CPUID leaves when they are available to avoid calibration.  It's on my
todo list.

Re: 7.2: tsc timecounter running too fast on ESXi 7.5

[Scott Cheloha]

On Wed, Oct 26, 2022 at 07:36:28AM -0700, James J. Lippard wrote:
> On Wed, Oct 26, 2022 at 04:33:23AM -0500, Scott Cheloha wrote:
> > Thank you for testing, let's take a look.
> > [...]
> > I don't know how to explain this.  Maybe another developer will read
> > this and spot something I'm missing.  Or maybe this is a known issue
> > and I'm just not finding a reference to it online.
> > 
> > The simplest workaround is to skip installing acpitimer_delay() with
> > delay_init() during acpitimerattach().  The attached patch does this.
> 
> Can confirm that this works.

Good.

> > I don't know if this problem persists after boot.  If it does, using
> > the acpitimer0 timecounter may yield strange results in the VM.  I
> > recommend not using the acpitimer0 timecounter until the problem is
> > better understood.  A calibrated TSC is going to be a better
> > timecounter anyway.
> > 
> > There might be a second workaround.  Kalabic mentions here in the
> > other thread about this problem:
> > 
> > https://marc.info/?l=openbsd-bugs=14949825616=2
> > 
> > ... that changing the ESXi option "Guest OS Version" from "FreeBSD
> > (32-bit)" to "FreeBSD (64-bit)" seemed to fix the problem on his
> > version of ESXi.  Does that work for you?  I don't know what the other
> > consequences of that configuration change are, but it might be worth a
> > try if you prefer to run 7.2-RELEASE or 7.2-STABLE instead of patching
> > -current.
> 
> I can also confirm that this works as a workaround on the stock 7.2 kernel.
> I also booted with the last kernel with debugging info with this workaround;
> dmesg for that is below.

Even better, and thank you for double-checking with the patched
kernel.

> > Do you have VMware support?  Is there any way for you to report this
> > problem to them?  It's unlikely they explicitly support running an
> > OpenBSD guest, but it's plausible this issue could affect other
> > operating systems.  I can't imagine OpenBSD is reading the ACPI PM
> > timer differently than Linux or FreeBSD.
> 
> Unfortunately not, I only use the free vSphere ESXi.

Drat.

> OpenBSD 7.2-current (GENERIC.MP) #1: Tue Oct 25 20:09:51 MST 2022
> lipp...@chaos.int.discord.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
> [snip]
> measure_tsc_freq: indirect calibration with acpitimer0(1000), 3579545 Hz: 
> count 14211444 14569397 tsc 38873326169 39063325035 usecs 9: 197660 Hz
> measure_tsc_freq: direct calibration with acpitimer0(1000), 3579545 Hz: 
> cycles 357958 tsc 190001742: 188842 Hz
> measure_tsc_freq: indirect calibration with acpitimer0(1000), 3579545 Hz: 
> count 14939119 15297049 tsc 39259571275 39449557759 usecs 3: 187839 Hz
> measure_tsc_freq: direct calibration with acpitimer0(1000), 3579545 Hz: 
> cycles 357955 tsc 18897: 186316 Hz
> measure_tsc_freq: indirect calibration with acpitimer0(1000), 3579545 Hz: 
> count 15666102 16024022 tsc 39645448713 39835430133 usecs 0: 194200 Hz
> measure_tsc_freq: direct calibration with acpitimer0(1000), 3579545 Hz: 
> cycles 357954 tsc 18157: 184223 Hz
> [snip]
> acpihpet0 at acpi0: 14318179 Hz
> measure_tsc_freq: indirect calibration with acpihpet0(1000), 14318179 Hz: 
> count 8315 1439858 tsc 42184173245 42374137028 usecs 99980: 1900017833 Hz
> measure_tsc_freq: direct calibration with acpihpet0(1000), 14318179 Hz: 
> cycles 1431819 tsc 18907: 187610 Hz
> measure_tsc_freq: indirect calibration with acpihpet0(1000), 14318179 Hz: 
> count 2894563 4326110 tsc 42567173659 42757137699 usecs 99981: 191400 Hz
> measure_tsc_freq: direct calibration with acpihpet0(1000), 14318179 Hz: 
> cycles 1431826 tsc 19836: 187611 Hz
> measure_tsc_freq: indirect calibration with acpihpet0(1000), 14318179 Hz: 
> count 5781139 7212684 tsc 42950217351 43140181114 usecs 99980: 1900017633 Hz
> measure_tsc_freq: direct calibration with acpihpet0(1000), 14318179 Hz: 
> cycles 1431826 tsc 19909: 188341 Hz

This looks right.

In summary:

- OpenBSD 7.2 amd64 kernel TSC and lapic calibration is broken on
  (at least) some ESXi 6.0 and ESXi 7.5 hosts under the VM configuration
  "FreeBSD (32-bit)".  The ACPI PM timer seemingly accelerates when we
  read it repeatedly during boot.

- Workaround 1 is to change the configuration to "FreeBSD (64-bit)".

- Workaround 2 is to not install acpitimer_delay() with delay_init()
  during acpitimerattach().

Re: 7.2: tsc timecounter running too fast on ESXi 7.5

[Scott Cheloha]

On Tue, Oct 25, 2022 at 09:00:33PM -0700, James J. Lippard wrote:
> On Tue, Oct 25, 2022 at 09:20:05PM -0500, Scott Cheloha wrote:
> > On Tue, Oct 25, 2022 at 02:24:24PM -0700, James J. Lippard wrote:
> > > I'm one of several people experiencing this issue with OpenBSD 7.2 on
> > > VMware ESXi 7.5. Scott C. has given me help in trying to track the issue
> > > down; a patched -current kernel to remove the acpi_delay code added in
> > > 7.2 makes the issue go away.
> > 
> > Thanks for your report.
> > 
> > I have one more patch for you to try.  Attached at the end.  Hopefully
> > it will confirm the root problem.  Send the resulting dmesg and we'll
> > see whether the problem is actually the acpitimer(4).
> 
> >[...]
> > Okay, here is the third patch.  Revert the earlier one and boot this.
> 
> Here's the dmesg output running with this new patch:

Thank you for testing, let's take a look.

> OpenBSD 7.2-current (GENERIC.MP) #1: Tue Oct 25 20:09:51 MST 2022
> lipp...@chaos.int.discord.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
> [snip]
> acpitimer0 at acpi0: 3579545 Hz, 24 bits
> acpimadt0 at acpi0 addr 0xfee0: PC-AT compat
> cpu0 at mainbus0: apid 0 (boot processor)
> cpu0: Intel(R) Xeon(R) CPU D-1528 @ 1.90GHz, 1899.77 MHz, 06-56-03
> cpu0: 
> FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,MMX,FXSR,SSE,SSE2,SS,SSE3,PCLMUL,SSSE3,FMA3,CX16,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,HV,NXE,PAGE1GB,RDTSCP,LONG,LAHF,ABM,3DNOWP,PERF,ITSC,FSGSBASE,TSC_ADJUST,BMI1,AVX2,SMEP,BMI2,ERMS,INVPCID,RDSEED,ADX,SMAP,MD_CLEAR,IBRS,IBPB,STIBP,L1DF,SSBD,ARAT,XSAVEOPT,MELTDOWN
> cpu0: 32KB 64b/line 8-way D-cache, 32KB 64b/line 8-way I-cache, 256KB 
> 64b/line 8-way L2 cache, 9MB 64b/line 12-way L3 cache
> measure_tsc_freq: indirect calibration with acpitimer0(1000), 3579545 Hz: 
> count 12840801 13198720 tsc 8350048970 8540029885 usecs 0: 189149 Hz
> measure_tsc_freq: direct calibration with acpitimer0(1000), 3579545 Hz: 
> cycles 357969 tsc 62919804: 629172553 Hz
> measure_tsc_freq: indirect calibration with acpitimer0(1000), 3579545 Hz: 
> count 13562994 13686416 tsc 8608912502 8798895525 usecs 34479: (failed)
> measure_tsc_freq: indirect calibration with acpitimer0(1000), 3579545 Hz: 
> count 13692684 14050605 tsc 880961 8992204988 usecs 0: 1900010271 Hz
> measure_tsc_freq: direct calibration with acpitimer0(1000), 3579545 Hz: 
> cycles 357969 tsc 64754894: 647522710 Hz

When we do "indirect calibration," we're using delay(9) to spin for
~100,000 microseconds in between reads of the reference timer and the
TSC.  In this case, the underlying delay(9) implementation is
i8254_delay().  This method calibrates the TSC to 1900 MHz.  For
example, in the first indirect calibration round we get:

  (tsc2 - tsc1) * acpitimer-frequency / (acpitimer2 - acpitimer1)
= (8540029885 - 8350048970) * 3579545 / (13198720 - 12840801)
= 187581

or roughly 1900 MHz.  The result printed in the dmesg (189149) is
a little different because the math in the kernel is a little
different.  The third indirect calibration round yields basically the
same result (1900010271).

When we do "direct calibration," we're reading the reference timer
itself repeatedly to spin for ~100,000 microseconds and accumulating a
count of reference timer cycles and TSC cycles as we spin.  This
method calibrates the TSC to ~630 MHz.  For example, in the first
direct calibration round we get:

  tsc-cycles * acpitimer-frequency / acpitimer-cycles
= 62919804 * 3579545 / 357969
= 629172553

or roughly 630 MHz.  The second indirect calibration round yields a
similar result (647522710).

Based on these numbers, I think the virtual ACPI PM Timer on this ESXi
VM accelerates beyond 3579545 Hz when it is read repeatedly and then
decelerates back down to the nominal frequency when it is read less
frequently.

I don't think the TSC itself has a non-constant frequency.  When we
calibrate it later with the HPET, both indirect calibration using the
local apic timer to spin and direct calibration using only the HPET
yield a TSC frequency of ~1900 MHz:

> [snip]
> cpu0: apic clock running at 65MHz
> delay_init: changing delay implementation: 0 -> 3000

(Here we switch from i8254_delay() to lapic_delay().)

> [snip]
> acpihpet0 at acpi0: 14318179 Hz
> measure_tsc_freq: indirect calibration with acpihpet0(1000), 14318179 Hz: 
> count 7984 1439544 tsc 11218877272 11408843078 usecs 99981: 1900019063 Hz
> measure_tsc_freq: direct calibration with acpihpet0(1000), 14318179 Hz: 
> cycles 1431817 tsc 18744: 188634 Hz
> measure_tsc_freq: indirect calibration with acpihpet0(1000), 14318179 Hz: 
> count 2894172 4325743 tsc 116018

Re: 7.2: tsc timecounter running too fast on ESXi 7.5

[Scott Cheloha]

On Tue, Oct 25, 2022 at 02:24:24PM -0700, James J. Lippard wrote:
> I'm one of several people experiencing this issue with OpenBSD 7.2 on
> VMware ESXi 7.5. Scott C. has given me help in trying to track the issue
> down; a patched -current kernel to remove the acpi_delay code added in
> 7.2 makes the issue go away.

Thanks for your report.

I have one more patch for you to try.  Attached at the end.  Hopefully
it will confirm the root problem.  Send the resulting dmesg and we'll
see whether the problem is actually the acpitimer(4).

> Below is output from sysctl machdep, sysctl hw, and dmesg:
> 
> [...]
> machdep.tscfreq=1900013052
> machdep.invarianttsc=1

This is probably the true TSC frequency...

> sysctl hw:
> hw.machine=amd64
> hw.model=Intel(R) Xeon(R) CPU D-1528 @ 1.90GHz

... it would match the nominal CPU frequency listed in the CPU string.

I'm going to snip some of these dmesgs for reference, too.

> dmesg (which includes 7.1, post-upgrade, and with patched -current
> kernel):
> 
> OpenBSD 7.1 (GENERIC.MP) #3: Sun May 15 10:27:01 MDT 2022
> 
> r...@syspatch-71-amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
> real mem = 6424494080 (6126MB)
> avail mem = 6212485120 (5924MB)
> random: good seed from bootblocks
> mpath0 at root
> scsibus0 at mpath0: 256 targets
> mainbus0 at root
> bios0 at mainbus0: SMBIOS rev. 2.7 @ 0xe0010 (242 entries)
> bios0: vendor Phoenix Technologies LTD version "6.00" date 11/12/2020
> bios0: VMware, Inc. VMware Virtual Platform
> acpi0 at bios0: ACPI 4.0
> acpi0: sleep states S0 S1 S4 S5
> acpi0: tables DSDT FACP BOOT APIC MCFG SRAT HPET WAET
> acpi0: wakeup devices PCI0(S3) USB_(S1) P2P0(S3) S1F0(S3) S2F0(S3) S8F0(S3) 
> S16F(S3) S18F(S3) S22F(S3) S23F(S3) S24F(S3) S25F(S3) PE40(S3) S1F0(S3) 
> PE50(S3) S1F0(S3) [...]
> acpitimer0 at acpi0: 3579545 Hz, 24 bits
> acpimadt0 at acpi0 addr 0xfee0: PC-AT compat
> cpu0 at mainbus0: apid 0 (boot processor)
> cpu0: Intel(R) Xeon(R) CPU D-1528 @ 1.90GHz, 1899.75 MHz, 06-56-03
> cpu0: 
> FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,MMX,FXSR,SSE,SSE2,SS,SSE3,PCLMUL,SSSE3,FMA3,CX16,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,HV,NXE,PAGE1GB,RDTSCP,LONG,LAHF,ABM,3DNOWP,PERF,ITSC,FSGSBASE,TSC_ADJUST,BMI1,AVX2,SMEP,BMI2,ERMS,INVPCID,RDSEED,ADX,SMAP,MD_CLEAR,IBRS,IBPB,STIBP,L1DF,SSBD,ARAT,XSAVEOPT,MELTDOWN
> cpu0: 256KB 64b/line 8-way L2 cache
> cpu0: smt 0, core 0, package 0
> mtrr: Pentium Pro MTRR support, 8 var ranges, 88 fixed ranges
> cpu0: apic clock running at 65MHz
> cpu1 at mainbus0: apid 2 (application processor)
> cpu1: Intel(R) Xeon(R) CPU D-1528 @ 1.90GHz, 1899.62 MHz, 06-56-03
> cpu1: 
> FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,MMX,FXSR,SSE,SSE2,SS,SSE3,PCLMUL,SSSE3,FMA3,CX16,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,HV,NXE,PAGE1GB,RDTSCP,LONG,LAHF,ABM,3DNOWP,PERF,ITSC,FSGSBASE,TSC_ADJUST,BMI1,AVX2,SMEP,BMI2,ERMS,INVPCID,RDSEED,ADX,SMAP,MD_CLEAR,IBRS,IBPB,STIBP,L1DF,SSBD,ARAT,XSAVEOPT,MELTDOWN
> cpu1: 256KB 64b/line 8-way L2 cache
> cpu1: disabling user TSC (skew=-2507)
> cpu1: smt 0, core 0, package 2
> ioapic0 at mainbus0: apid 1 pa 0xfec0, version 20, 24 pins
> acpimcfg0 at acpi0
> acpimcfg0: addr 0xf000, bus 0-127
> acpihpet0 at acpi0: 14318179 Hz

7.1-release.  This dmesg worked right.

> OpenBSD 7.2 (GENERIC.MP) #758: Tue Sep 27 11:57:54 MDT 2022
> dera...@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
> real mem = 6424494080 (6126MB)
> avail mem = 6212378624 (5924MB)
> random: good seed from bootblocks
> mpath0 at root
> scsibus0 at mpath0: 256 targets
> mainbus0 at root
> bios0 at mainbus0: SMBIOS rev. 2.7 @ 0xe0010 (242 entries)
> bios0: vendor Phoenix Technologies LTD version "6.00" date 11/12/2020
> bios0: VMware, Inc. VMware Virtual Platform
> acpi0 at bios0: ACPI 4.0
> acpi0: sleep states S0 S1 S4 S5
> acpi0: tables DSDT FACP BOOT APIC MCFG SRAT HPET WAET
> acpi0: wakeup devices PCI0(S3) USB_(S1) P2P0(S3) S1F0(S3) S2F0(S3) S8F0(S3) 
> S16F(S3) S18F(S3) S22F(S3) S23F(S3) S24F(S3) S25F(S3) PE40(S3) S1F0(S3) 
> PE50(S3) S1F0(S3) [...]
> acpitimer0 at acpi0: 3579545 Hz, 24 bits
> acpimadt0 at acpi0 addr 0xfee0: PC-AT compat
> cpu0 at mainbus0: apid 0 (boot processor)
> cpu0: Intel(R) Xeon(R) CPU D-1528 @ 1.90GHz, 586.43 MHz, 06-56-03
> cpu0: 
> FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,MMX,FXSR,SSE,SSE2,SS,SSE3,PCLMUL,SSSE3,FMA3,CX16,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,HV,NXE,PAGE1GB,RDTSCP,LONG,LAHF,ABM,3DNOWP,PERF,ITSC,FSGSBASE,TSC_ADJUST,BMI1,AVX2,SMEP,BMI2,ERMS,INVPCID,RDSEED,ADX,SMAP,MD_CLEAR,IBRS,IBPB,STIBP,L1DF,SSBD,ARAT,XSAVEOPT,MELTDOWN
> cpu0: 32KB 64b/line 8-way D-cache, 32KB 64b/line 8-way I-cache, 256KB 
> 64b/line 8-way L2 cache, 9MB 64b/line 12-way L3 cache
> cpu0: smt 0, core 0, package 0
> mtrr: Pentium Pro MTRR support, 8 var ranges, 88 

Re: Had to set 'kern.timecounter.hardware' to 'acpitimer0' to fix system clock going too fast

[Scott Cheloha]

On Mon, Oct 24, 2022 at 08:26:30AM -0500, Scott Cheloha wrote:
> On Sun, Oct 23, 2022 at 02:07:12PM +0200, Kalabic S. wrote:
> > [...]
> 
> > machdep.cpuvendor=GenuineIntel
> > machdep.cpuid=0x306a9
> > machdep.cpufeature=0x1fbbfbff
> > machdep.tscfreq=745206414
> > machdep.invarianttsc=1
> 
> And yeah, your TSC frequency is astoundingly high.  Way higher than
> anything I have ever seen.

Sorry, what I should have said was: that TSC frequency is too *low*
for your machine.  I miscounted the number of decimal digits.

To be clear: the measured TSC frequency of 745 MHz seems too low.

Re: Had to set 'kern.timecounter.hardware' to 'acpitimer0' to fix system clock going too fast

[Scott Cheloha]

On Sun, Oct 23, 2022 at 02:07:12PM +0200, Kalabic S. wrote:
> On 23/10/2022 12:28, Scott Cheloha wrote:
> > On Fri, Oct 21, 2022 at 12:28:26AM +0200, Kalabic S. wrote:
> > > Hello,
> > > 
> > > I noticed a system clock issue after upgrade from 7.1 to 7.2, clock 
> > > started
> > > to run really fast, almost at 10x speed or so. It is a virtual machine 
> > > guest
> > > on ESXi 6.0 host, VM is used as a main Internet router for my home network
> > > (PPPoE over fiber). Both host and VM are configured with date/time in UTC
> > > timezone.
> > > 
> > > Long story short, setting 'kern.timecounter.hardware' to 'acpitimer0' has
> > > fixed it.
> > > 
> > > It did not make any difference if ntpd service was enabled or disabled.
> > 
> > Please provide a dmesg and the output of
> > 
> > $ sysctl hw
> > 
> > and
> > 
> > $ sysctl machdep
> > 
> > A dmesg from the VM before you upgraded will also help.

I'm not seeing one here.  I guess I'll just do a little guesswork.

> > If you have some kind of configuration file for the ESXi host and the
> > VM, that will also help.  I don't know anything about ESXi, but it
> > will help to look at what sort of settings you are using.

Also not seeing this here.  If you provide one it might save a lot of
time chasing non-problems.

> Attached output to this mail.

Thanks, let's take a peek.

> OpenBSD 7.2 (GENERIC.MP) #758: Tue Sep 27 11:57:54 MDT 2022
> dera...@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
> real mem = 1055850496 (1006MB)
> avail mem = 1006510080 (959MB)
> random: good seed from bootblocks
> mpath0 at root
> scsibus0 at mpath0: 256 targets
> mainbus0 at root
> bios0 at mainbus0: SMBIOS rev. 2.4 @ 0xe0010 (556 entries)
> bios0: vendor Phoenix Technologies LTD version "6.00" date 09/21/2015
> bios0: VMware, Inc. VMware Virtual Platform

Okay, we're in a VMware guest, no surprises there.

> acpi0 at bios0: ACPI 4.0
> acpi0: sleep states S0 S1 S4 S5
> acpi0: tables DSDT FACP BOOT APIC MCFG SRAT HPET WAET
> acpi0: wakeup devices PCI0(S3) USB_(S1) P2P0(S3) S1F0(S3) S2F0(S3) S8F0(S3) 
> S16F(S3) S17F(S3) S18F(S3) S22F(S3) S23F(S3) S24F(S3) S25F(S3) PE40(S3) 
> S1F0(S3) PE50(S3) [...]
> acpitimer0 at acpi0: 3579545 Hz, 24 bits

You have a 24-bit virtual ACPI PM timer.

At this point in the boot, we will have switched from i8254_delay() to
using acpitimer_delay().

We probably also calibrate the TSC with acpitimer(4) here,
or near here.

> acpimadt0 at acpi0 addr 0xfee0: PC-AT compat
> cpu0 at mainbus0: apid 0 (boot processor)
> cpu0: Intel(R) Core(TM) i5-3570 CPU @ 3.40GHz, 745.35 MHz, 06-3a-09

The bogomips measurement is very, very low compared to the speed
advertised in the CPU string.

Not necessarily an error, but odd-looking, even in a VM.

> cpu0: 
> FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,MMX,FXSR,SSE,SSE2,SS,HTT,SSE3,PCLMUL,SSSE3,CX16,PCID,SSE4.1,SSE4.2,x2APIC,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,HV,NXE,RDTSCP,LONG,LAHF,PERF,ITSC,FSGSBASE,TSC_ADJUST,SMEP,ERMS,MD_CLEAR,IBRS,IBPB,STIBP,L1DF,SSBD,ARAT,MELTDOWN

TSC-related feature flags: TSC, DEADLINE, RDTSCP, ITSC, TSC_ADJUST

> cpu0: 32KB 64b/line 8-way D-cache, 32KB 64b/line 8-way I-cache, 256KB 
> 64b/line 8-way L2 cache, 6MB 64b/line 12-way L3 cache
> cpu0: smt 0, core 0, package 0
> mtrr: Pentium Pro MTRR support, 8 var ranges, 88 fixed ranges
> cpu0: apic clock running at 15MHz

This looks low.

I don't know precisely what the hypervisor does to the local apic
timer frequency, and I don't have an old dmesg for reference, but my
guess is that this value is wrong.

At this point in the boot we have switched from acpitimer_delay() to
lapic_delay().

> cpu1 at mainbus0: apid 1 (application processor)
> cpu1: Intel(R) Core(TM) i5-3570 CPU @ 3.40GHz, 813.12 MHz, 06-3a-09
> cpu1: 
> FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,MMX,FXSR,SSE,SSE2,SS,HTT,SSE3,PCLMUL,SSSE3,CX16,PCID,SSE4.1,SSE4.2,x2APIC,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,HV,NXE,RDTSCP,LONG,LAHF,PERF,ITSC,FSGSBASE,TSC_ADJUST,SMEP,ERMS,MD_CLEAR,IBRS,IBPB,STIBP,L1DF,SSBD,ARAT,MELTDOWN
> cpu1: 32KB 64b/line 8-way D-cache, 32KB 64b/line 8-way I-cache, 256KB 
> 64b/line 8-way L2 cache, 6MB 64b/line 12-way L3 cache
> cpu1: smt 0, core 1, package 0
> cpu2 at mainbus0: apid 2 (application processor)
> cpu2: Intel(R) Core(TM) i5-3570 CPU @ 3.40GHz, 813.24 MHz, 06-3a-09
> cpu2: 
> FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,MMX,FXSR,SSE,SSE2,SS,HTT,SSE3,PCLMUL,SSSE3,CX16,PCID,SSE4.1,SSE4.2,x2APIC,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,HV,NXE,RDTSCP,LONG,LAHF,PERF,I

Re: Had to set 'kern.timecounter.hardware' to 'acpitimer0' to fix system clock going too fast

[Scott Cheloha]

On Fri, Oct 21, 2022 at 12:28:26AM +0200, Kalabic S. wrote:
> Hello,
> 
> I noticed a system clock issue after upgrade from 7.1 to 7.2, clock started
> to run really fast, almost at 10x speed or so. It is a virtual machine guest
> on ESXi 6.0 host, VM is used as a main Internet router for my home network
> (PPPoE over fiber). Both host and VM are configured with date/time in UTC
> timezone.
> 
> Long story short, setting 'kern.timecounter.hardware' to 'acpitimer0' has
> fixed it.
> 
> It did not make any difference if ntpd service was enabled or disabled.

Please provide a dmesg and the output of

$ sysctl hw

and

$ sysctl machdep

A dmesg from the VM before you upgraded will also help.

If you have some kind of configuration file for the ESXi host and the
VM, that will also help.  I don't know anything about ESXi, but it
will help to look at what sort of settings you are using.

Re: i386 boot hangs: "init: can't open /dev/console: Device not configured"

[Scott Cheloha]

On Thu, Sep 01, 2022 at 04:26:18PM -0500, Scott Cheloha wrote:
> Hi,
> 
> mlarkin@ said someone needed to verify my i386/lapic.c changes on real
> hardware:
> 
> https://marc.info/?l=openbsd-tech=166186787532304=2
> 
> So, like a chucklehead, I thought "how hard could it be?" and tried
> installing OpenBSD/i386 to an external drive and booting my amd64
> laptop (Lenovo X1 Carbon 6th) from it.
> 
> The install -- booted from a USB-attached CD-ROM, installed to a USB-3
> external drive -- went fine.
> 
> When I tried to boot after installation, however, I hit a snag.
> init(8) hung the boot.  It kept printing:
> 
> init: can't open /dev/console: Device not configured
> init: can't open /dev/console: Device not configured
> init: can't open /dev/console: Device not configured
> 
> every fifteen or so seconds.  Keyboard was unresponsive.
> 
> A little searching led me to this reddit post from a few years ago:
> 
> https://reddit.com/r/openbsd/comments/8zganh/new_amd64_install_says_cant_open_devconsole/
> 
> A commenter on that post suggests that disabling 'inteldrm' and/or
> 'radeondrm' during boot from config(8) might do the trick.  It worked.
> With those drivers disabled, init(8) doesn't trip over /dev/console
> and the machine finishes booting, is stable, etc.  Obviously I don't
> have accelerated graphics, but the machine is otherwise perfectly
> usable from the console and vterms.
> 
> I have never seen this issue booting OpenBSD/amd64 on this (or any
> other) machine before.
> 
> I have attached both the amd64 dmesg and the i386 dmesg below.  Same
> machine, no changes to the BIOS between reboots.  They are booting
> from different disks: amd64 boots from the internal NVMe drive, i386
> boots from an external LaCiE drive over USB.
> 
> The issue persists on the i386 side even after installing all missing
> firmware.

Ping.

> OpenBSD 7.2-beta (GENERIC.MP) #0: Tue Aug 30 20:15:55 CDT 2022
> s...@jetsam.attlocal.net:/usr/src/sys/arch/amd64/compile/GENERIC.MP
> real mem = 17018175488 (16229MB)
> avail mem = 16354238464 (15596MB)
> random: good seed from bootblocks
> mpath0 at root
> scsibus0 at mpath0: 256 targets
> mainbus0 at root
> bios0 at mainbus0: SMBIOS rev. 3.0 @ 0xaa62d000 (63 entries)
> bios0: vendor LENOVO version "N23ET82W (1.57 )" date 07/21/2022
> bios0: LENOVO 20KHCTO1WW
> acpi0 at bios0: ACPI 5.0
> acpi0: sleep states S0 S3 S4 S5
> acpi0: tables DSDT FACP SSDT SSDT TPM2 UEFI SSDT SSDT HPET APIC MCFG ECDT 
> SSDT SSDT BOOT BATB SSDT SSDT SSDT LPIT WSMT SSDT SSDT SSDT DBGP DBG2 MSDM 
> DMAR NHLT ASF! FPDT UEFI
> acpi0: wakeup devices GLAN(S4) XHC_(S3) XDCI(S4) HDAS(S4) RP01(S4) PXSX(S4) 
> RP02(S4) PXSX(S4) PXSX(S4) RP04(S4) PXSX(S4) RP05(S4) PXSX(S4) RP06(S4) 
> PXSX(S4) RP07(S4) [...]
> acpitimer0 at acpi0: 3579545 Hz, 24 bits
> acpihpet0 at acpi0: 2399 Hz
> acpimadt0 at acpi0 addr 0xfee0: PC-AT compat
> cpu0 at mainbus0: apid 0 (boot processor)
> cpu0: Intel(R) Core(TM) i7-8650U CPU @ 1.90GHz, 1795.82 MHz, 06-8e-0a
> cpu0: 
> FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,SMX,EST,TM2,SSSE3,SDBG,FMA3,CX16,xTPR,PDCM,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,NXE,PAGE1GB,RDTSCP,LONG,LAHF,ABM,3DNOWP,PERF,ITSC,FSGSBASE,TSC_ADJUST,SGX,BMI1,HLE,AVX2,SMEP,BMI2,ERMS,INVPCID,RTM,MPX,RDSEED,ADX,SMAP,CLFLUSHOPT,PT,SRBDS_CTRL,MD_CLEAR,TSXFA,IBRS,IBPB,STIBP,L1DF,SSBD,SENSOR,ARAT,XSAVEOPT,XSAVEC,XGETBV1,XSAVES,MELTDOWN
> cpu0: 32KB 64b/line 8-way D-cache, 32KB 64b/line 8-way I-cache, 256KB 
> 64b/line 4-way L2 cache, 8MB 64b/line 16-way L3 cache
> cpu0: smt 0, core 0, package 0
> mtrr: Pentium Pro MTRR support, 10 var ranges, 88 fixed ranges
> cpu0: apic clock running at 24MHz
> cpu0: mwait min=64, max=64, C-substates=0.2.1.2.4.1.1.1, IBE
> cpu1 at mainbus0: apid 2 (application processor)
> cpu1: Intel(R) Core(TM) i7-8650U CPU @ 1.90GHz, 1795.82 MHz, 06-8e-0a
> cpu1: 
> FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,SMX,EST,TM2,SSSE3,SDBG,FMA3,CX16,xTPR,PDCM,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,NXE,PAGE1GB,RDTSCP,LONG,LAHF,ABM,3DNOWP,PERF,ITSC,FSGSBASE,TSC_ADJUST,SGX,BMI1,HLE,AVX2,SMEP,BMI2,ERMS,INVPCID,RTM,MPX,RDSEED,ADX,SMAP,CLFLUSHOPT,PT,SRBDS_CTRL,MD_CLEAR,TSXFA,IBRS,IBPB,STIBP,L1DF,SSBD,SENSOR,ARAT,XSAVEOPT,XSAVEC,XGETBV1,XSAVES,MELTDOWN
> cpu1: 32KB 64b/line 8-way D-cache, 32KB 64b/line 8-way I-cache, 256KB 
> 64b/line 4-way L2 cache, 8MB 64b/line 16-way L3 cache
> cpu1: smt 0, core 1, package 0
> cpu2 at mainbus0: apid 4 (application proc

i386 boot hangs: "init: can't open /dev/console: Device not configured"

[Scott Cheloha]

Hi,

mlarkin@ said someone needed to verify my i386/lapic.c changes on real
hardware:

https://marc.info/?l=openbsd-tech=166186787532304=2

So, like a chucklehead, I thought "how hard could it be?" and tried
installing OpenBSD/i386 to an external drive and booting my amd64
laptop (Lenovo X1 Carbon 6th) from it.

The install -- booted from a USB-attached CD-ROM, installed to a USB-3
external drive -- went fine.

When I tried to boot after installation, however, I hit a snag.
init(8) hung the boot.  It kept printing:

init: can't open /dev/console: Device not configured
init: can't open /dev/console: Device not configured
init: can't open /dev/console: Device not configured

every fifteen or so seconds.  Keyboard was unresponsive.

A little searching led me to this reddit post from a few years ago:

https://reddit.com/r/openbsd/comments/8zganh/new_amd64_install_says_cant_open_devconsole/

A commenter on that post suggests that disabling 'inteldrm' and/or
'radeondrm' during boot from config(8) might do the trick.  It worked.
With those drivers disabled, init(8) doesn't trip over /dev/console
and the machine finishes booting, is stable, etc.  Obviously I don't
have accelerated graphics, but the machine is otherwise perfectly
usable from the console and vterms.

I have never seen this issue booting OpenBSD/amd64 on this (or any
other) machine before.

I have attached both the amd64 dmesg and the i386 dmesg below.  Same
machine, no changes to the BIOS between reboots.  They are booting
from different disks: amd64 boots from the internal NVMe drive, i386
boots from an external LaCiE drive over USB.

The issue persists on the i386 side even after installing all missing
firmware.

OpenBSD 7.2-beta (GENERIC.MP) #0: Tue Aug 30 20:15:55 CDT 2022
s...@jetsam.attlocal.net:/usr/src/sys/arch/amd64/compile/GENERIC.MP
real mem = 17018175488 (16229MB)
avail mem = 16354238464 (15596MB)
random: good seed from bootblocks
mpath0 at root
scsibus0 at mpath0: 256 targets
mainbus0 at root
bios0 at mainbus0: SMBIOS rev. 3.0 @ 0xaa62d000 (63 entries)
bios0: vendor LENOVO version "N23ET82W (1.57 )" date 07/21/2022
bios0: LENOVO 20KHCTO1WW
acpi0 at bios0: ACPI 5.0
acpi0: sleep states S0 S3 S4 S5
acpi0: tables DSDT FACP SSDT SSDT TPM2 UEFI SSDT SSDT HPET APIC MCFG ECDT SSDT 
SSDT BOOT BATB SSDT SSDT SSDT LPIT WSMT SSDT SSDT SSDT DBGP DBG2 MSDM DMAR NHLT 
ASF! FPDT UEFI
acpi0: wakeup devices GLAN(S4) XHC_(S3) XDCI(S4) HDAS(S4) RP01(S4) PXSX(S4) 
RP02(S4) PXSX(S4) PXSX(S4) RP04(S4) PXSX(S4) RP05(S4) PXSX(S4) RP06(S4) 
PXSX(S4) RP07(S4) [...]
acpitimer0 at acpi0: 3579545 Hz, 24 bits
acpihpet0 at acpi0: 2399 Hz
acpimadt0 at acpi0 addr 0xfee0: PC-AT compat
cpu0 at mainbus0: apid 0 (boot processor)
cpu0: Intel(R) Core(TM) i7-8650U CPU @ 1.90GHz, 1795.82 MHz, 06-8e-0a
cpu0: 
FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,SMX,EST,TM2,SSSE3,SDBG,FMA3,CX16,xTPR,PDCM,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,NXE,PAGE1GB,RDTSCP,LONG,LAHF,ABM,3DNOWP,PERF,ITSC,FSGSBASE,TSC_ADJUST,SGX,BMI1,HLE,AVX2,SMEP,BMI2,ERMS,INVPCID,RTM,MPX,RDSEED,ADX,SMAP,CLFLUSHOPT,PT,SRBDS_CTRL,MD_CLEAR,TSXFA,IBRS,IBPB,STIBP,L1DF,SSBD,SENSOR,ARAT,XSAVEOPT,XSAVEC,XGETBV1,XSAVES,MELTDOWN
cpu0: 32KB 64b/line 8-way D-cache, 32KB 64b/line 8-way I-cache, 256KB 64b/line 
4-way L2 cache, 8MB 64b/line 16-way L3 cache
cpu0: smt 0, core 0, package 0
mtrr: Pentium Pro MTRR support, 10 var ranges, 88 fixed ranges
cpu0: apic clock running at 24MHz
cpu0: mwait min=64, max=64, C-substates=0.2.1.2.4.1.1.1, IBE
cpu1 at mainbus0: apid 2 (application processor)
cpu1: Intel(R) Core(TM) i7-8650U CPU @ 1.90GHz, 1795.82 MHz, 06-8e-0a
cpu1: 
FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,SMX,EST,TM2,SSSE3,SDBG,FMA3,CX16,xTPR,PDCM,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,NXE,PAGE1GB,RDTSCP,LONG,LAHF,ABM,3DNOWP,PERF,ITSC,FSGSBASE,TSC_ADJUST,SGX,BMI1,HLE,AVX2,SMEP,BMI2,ERMS,INVPCID,RTM,MPX,RDSEED,ADX,SMAP,CLFLUSHOPT,PT,SRBDS_CTRL,MD_CLEAR,TSXFA,IBRS,IBPB,STIBP,L1DF,SSBD,SENSOR,ARAT,XSAVEOPT,XSAVEC,XGETBV1,XSAVES,MELTDOWN
cpu1: 32KB 64b/line 8-way D-cache, 32KB 64b/line 8-way I-cache, 256KB 64b/line 
4-way L2 cache, 8MB 64b/line 16-way L3 cache
cpu1: smt 0, core 1, package 0
cpu2 at mainbus0: apid 4 (application processor)
cpu2: Intel(R) Core(TM) i7-8650U CPU @ 1.90GHz, 1795.82 MHz, 06-8e-0a
cpu2: 

Re: Interrupts hover above 40% when idle on Dell Latitude E7450

[Scott Cheloha]

On Sun, Jan 30, 2022 at 10:41:34AM -0500, Ryan Kavanagh wrote:
> On Sun, Jan 30, 2022 at 12:39:02AM -0600, Scott Cheloha wrote:
> > > btrace -e 'profile:hz:100 { @[kstack] = count(); }' > /tmp/btrace.out
> > > 
> > > for ten seconds and ran the output through
> > > 
> > > https://github.com/brendangregg/FlameGraph/raw/master/stackcollapse-bpftrace.pl
> > > https://github.com/brendangregg/FlameGraph/raw/master/flamegraph.pl
> > > 
> > > The output of stackcollapse-bpftrace.pl and flamegraph.pl are attached
> > > as btrace.collapsed and btrace.svg.
> > 
> > The flamegraph suggests that you spent 10% of that time servicing
> > ichiic(4) interrupts from idle.
> > 
> > That could be a fluke though.
> 
> In case it was a fluke, I've regenerated the flamegraph on 7.0
> GENERIC.MP#293 amd64 using 10 seconds of output on an idle machine.
> Please see attached.
> 
> > What does the main systat view look like in the interrupt column?
> > 
> > $ systat 1
> 
> Again on #293:
> 
> Interrupts(range after idling for a few seconds)
>  247 total(235-260)
>  200 clock(200-200)
>   21 ipi  (16-23)
>1 acpi0(0-1)
>6 inteldrm (5-7)
>  azalia1  (0-0)
>   11 iwm0 (10-16)
>  ehci0(0-0)
>1 ahci0(0-1)
>1 ichiic0  (0-1)
>6 pckbc0   (0-0)
>  pckbc0   (0-0)

Based on these numbers and the similar-looking flamegraph I'd say
you're spending a relatively large amount of time handling ichiic(4)
interrupts.

I don't know anything about that device but my guess is that it is
slow if you're spending that much time in x86_bus_space_io_read_1()
and its _write_1() counterpart.

Someone else is going to have to weigh in on what might be the cause
and solution.

Thank you providing the traces.

Re: Interrupts hover above 40% when idle on Dell Latitude E7450

[Scott Cheloha]

On Mon, Jan 10, 2022 at 10:36:41AM -0500, Ryan Kavanagh wrote:
> >Synopsis:high interrupt processing time on Dell Latitude E7450
> >Category:kernel amd64
> >Environment:
>   System  : OpenBSD 7.0
>   Details : OpenBSD 7.0-current (GENERIC.MP) #242: Sat Jan  8 
> 12:33:38 MST 2022
>
> dera...@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
> 
>   Architecture: OpenBSD.amd64
>   Machine : amd64
> >Description:
> 
> I installed OpenBSD 7.0 on a Dell Latitude E7450. The installer had me
> using GENERIC, and interrupts hovered above 40%-45% when idle. I
> upgraded to 7.0-current with the same issue. The laptop ran hot,
> presumably as a result of the high interrupt processing time.
> 
> Here is the output of vmstat -i under 7.0-current / GENERIC:
> 
> interrupt   total rate
> irq0/clock 885333   99
> irq96/acpi0  17890
> irq144/inteldrm0   117024   13
> irq114/em0  124141
> irq176/azalia1   16680
> irq115/iwm0416586   47
> irq102/ehci0  2210
> irq103/ahci0   124340   14
> irq104/ichiic0   17700
> irq145/pckbc0   177101
> irq146/pckbc0   445885
> Total 1623443  183
> 
> Stuart Henderson suggested in the misc thread [0] that I try GENERIC.MP.
> After switching, top shows that CPU0 is spending roughly the same amount
> of time processing interrupts, while CPU1 is free to do other stuff.
> Representative capture:
> 
> CPU0 states: 18.6% user,  0.0% nice,  3.0% sys,  0.2% spin, 44.3% intr,
> 33.9% idle
> CPU1 states: 50.3% user,  0.0% nice,  5.0% sys,  1.6% spin,  0.0% intr,
> 43.1% idle
> 
> `systat vm` shows an Int% hovering around 20% (I imagine it's the mean
> of the two interrupt rates shown by top), with lows in the low 10% and
> highs in the low 30%.
> 
> My laptop does not seem to get as hot as quickly under GENERIC.MP, but
> it still gets pretty hot: hw.sensors.cpu0.temp0=86.00 degC after 5
> minutes when watching a video on Youtube in firefox.
> 
> vmstat -i under GENERIC.MP after being up ~35 minutes with light load:
> 
> interrupt   total rate
> irq0/clock 860124  399
> irq0/ipi   714019  331
> irq96/acpi0   4360
> irq144/inteldrm033945   15
> irq114/em0   79653
> irq176/azalia1  10
> irq115/iwm0 73471   34
> irq102/ehci0   730
> irq103/ahci044676   20
> irq104/ichiic04310
> irq145/pckbc064412
> irq146/pckbc031781
> Total 1744760  810
> 
> I ran
> 
> btrace -e 'profile:hz:100 { @[kstack] = count(); }' > /tmp/btrace.out
> 
> for ten seconds and ran the output through
> 
> https://github.com/brendangregg/FlameGraph/raw/master/stackcollapse-bpftrace.pl
> https://github.com/brendangregg/FlameGraph/raw/master/flamegraph.pl
> 
> The output of stackcollapse-bpftrace.pl and flamegraph.pl are attached
> as btrace.collapsed and btrace.svg.

The flamegraph suggests that you spent 10% of that time servicing
ichiic(4) interrupts from idle.

That could be a fluke though.

What does the main systat view look like in the interrupt column?

$ systat 1

Re: panic: ieee80211_set_link_state() calls rtm_80211info() from timeout context

[Scott Cheloha]

On Sat, Dec 04, 2021 at 08:40:42PM +0100, Stefan Sperling wrote:
> On Sat, Dec 04, 2021 at 09:32:40PM +0300, Vitaliy Makkoveev wrote:
> > I think rtm_80211info() could follow the if_link_state_change()
> > way and use task for that.
> 
> Indeed. I did not realize that if_link_state_change() schedules a task.
> 
> This means ieee80211_set_link_state() is already deferring some of its
> work to a task.

Probably should have mentioned this in my original mail.

> The patch below defers sending the 80211info message to a task as well.
> 
> I am keeping things simple for now and use systq (kernel-locked) instead
> of copying the argument-passing approach used by if_link_state_change().

All timeouts run under the kernel lock, so this is appropriate.

> Tested on iwm(4) 8265 with 'route monitor'.
> 
> ok?

I like the direction.  I have a few concerns noted below.

> diff 0b61c8235787960f0010ef627ea5b2c6309a81f0 
> de98c050ea709bdb8e26be40ab0cc82ef9afed80
> blob - 7bb68194dd78417b06c59f81d1ebbff4165203d8
> blob + 5b9a969258074fde29e21a33ac035cf170ec3b03
> --- sys/net80211/ieee80211.c
> +++ sys/net80211/ieee80211.c
> @@ -193,6 +193,7 @@ ieee80211_ifattach(struct ifnet *ifp)
>   if_addgroup(ifp, "wlan");
>   ifp->if_priority = IF_WIRELESS_DEFAULT_PRIORITY;
>  
> + task_set(>ic_rtm_80211info_task, ieee80211_rtm_80211info_task, ic);
>   ieee80211_set_link_state(ic, LINK_STATE_DOWN);
>  
>   timeout_set(>ic_bgscan_timeout, ieee80211_bgscan_timeout, ifp);
> @@ -203,6 +204,7 @@ ieee80211_ifdetach(struct ifnet *ifp)
>  {
>   struct ieee80211com *ic = (void *)ifp;
>  
> + task_del(systq, >ic_rtm_80211info_task);
>   timeout_del(>ic_bgscan_timeout);

Suppose the ic_bgscan_timeout timeout is running at the moment we're
running ieee80211_ifdetach().  Ignore the kernel lock for the moment,
think about the future.

If we delete the task before we delete the timeout and the timeout
then adds the task back onto the task queue, what happens?

My guess is you need to ensure the timeout is no longer running
*before* you delete the task.  Can you do timeout_del_barrier()
here?  See the attached patch.

>  
>   /*
> blob - 447a2676bfb250b7f917206549679d6ae68de1f6
> blob + 7e10fc1336067542c13d5607602e658ce2b3926b
> --- sys/net80211/ieee80211_proto.c
> +++ sys/net80211/ieee80211_proto.c
> @@ -1288,6 +1288,31 @@ justcleanup:
>  }
>  
>  void
> +ieee80211_rtm_80211info_task(void *arg)
> +{
> + struct ieee80211com *ic = arg;
> + struct ifnet *ifp = >ic_if;
> + struct if_ieee80211_data ifie;
> + int s = splnet();
> +
> + if (LINK_STATE_IS_UP(ifp->if_link_state)) {

Does this mean userspace can "miss" state transitions if the task runs
and the state has already changed back to not-up?

I don't know whether this would matter in practice, but it would be a
behavior change.

--

The rest of the patch looks good, running with it now on this:

$ dmesg | grep iwm0 | tail -n2
iwm0 at pci1 dev 0 function 0 "Intel Dual Band Wireless-AC 8265" rev 0x78, msi
iwm0: hw rev 0x230, fw ver 36.ca7b901d.0, address 98:3b:8f:ef:6b:ef

Unsure how `route monitor` exercises this path, but I've left it
running, too.

Index: ieee80211.c
===
RCS file: /cvs/src/sys/net80211/ieee80211.c,v
retrieving revision 1.85
diff -u -p -r1.85 ieee80211.c
--- ieee80211.c 11 Oct 2021 09:01:06 -  1.85
+++ ieee80211.c 5 Dec 2021 17:01:51 -
@@ -193,6 +193,7 @@ ieee80211_ifattach(struct ifnet *ifp)
if_addgroup(ifp, "wlan");
ifp->if_priority = IF_WIRELESS_DEFAULT_PRIORITY;
 
+   task_set(>ic_rtm_80211info_task, ieee80211_rtm_80211info_task, ic);
ieee80211_set_link_state(ic, LINK_STATE_DOWN);
 
timeout_set(>ic_bgscan_timeout, ieee80211_bgscan_timeout, ifp);
@@ -203,7 +204,8 @@ ieee80211_ifdetach(struct ifnet *ifp)
 {
struct ieee80211com *ic = (void *)ifp;
 
-   timeout_del(>ic_bgscan_timeout);
+   timeout_del_barrier(>ic_bgscan_timeout);
+   task_del(systq, >ic_rtm_80211info_task);
 
/*
 * Undo pseudo-driver changes. Pseudo-driver detach hooks could

panic: ieee80211_set_link_state() calls rtm_80211info() from timeout context

[Scott Cheloha]

Hit a witness panic during boot yesterday.  Can't repro, have never
seen it before.  The photo is a mess (ask if you want it) but the
backtrace is:

panic
witness_checkorder
rw_enter_write
solock
route input
ieee80211_set_link_state
ieee80211_recv_4way_msg3
ieee80211_eapol_key_input
ieee80211_decap
ieee80211_input_ba_flush
ieee80211_input_ba_gap_timeout
timeout_run
softclock_process_tick_timeout
sotclock

We're not allowed to take sleeping locks during the execution of a
timeout, hence the witness panic.

The backtrace omits that ieee80211_set_link_state() calls
rtm_80211info(), which calls route_input().

The guilty call is in ieee80211_proto.c, line 1327:

  1295  void
  1296  ieee80211_set_link_state(struct ieee80211com *ic, int nstate)
  1297  {
  1298  struct ifnet *ifp = >ic_if;
  1299  
  1300  switch (ic->ic_opmode) {

/* ... */

  1312  }
  1313  if (nstate != ifp->if_link_state) {
  1314  ifp->if_link_state = nstate;
  1315  if (LINK_STATE_IS_UP(nstate)) {
  1316  struct if_ieee80211_data ifie;
  1317  memset(, 0, sizeof(ifie));
  1318  ifie.ifie_nwid_len = ic->ic_bss->ni_esslen;
  1319  memcpy(ifie.ifie_nwid, ic->ic_bss->ni_essid,
  1320  sizeof(ifie.ifie_nwid));
  1321  memcpy(ifie.ifie_addr, ic->ic_bss->ni_bssid,
  1322  sizeof(ifie.ifie_addr));
  1323  ifie.ifie_channel = ieee80211_chan2ieee(ic,
  1324  ic->ic_bss->ni_chan);
  1325  ifie.ifie_flags = ic->ic_flags;
  1326  ifie.ifie_xflags = ic->ic_xflags;
  1327  rtm_80211info(>ic_if, );
  1328  }
  1329  if_link_state_change(ifp);
  1330  }
  1331  }

So if the link state is changing from not-up to up we send a routing
info message to userspace.

Typical solution would be to postpone the rtm_80211info() call to a
task, but I'm not familiar with this stack so maybe we can't do that?

Re: intel(4): edp_panel_vdd_on calls task_del(9) with NULL taskq

[Scott Cheloha]

On Thu, May 06, 2021 at 02:36:21PM +0200, Mark Kettenis wrote:
> > Date: Thu, 6 May 2021 21:59:12 +1000
> > From: Jonathan Gray 
> > 
> > On Wed, May 05, 2021 at 04:47:50PM -0500, Scott Cheloha wrote:
> > > 
> > > [...]
> > > 
> > > On a hunch I added additional parameter checks to task_add(9) and
> > > task_del(9) and caught intel(4) doing something strange.
> > > 
> > > [...]
> > > 
> > > And here is the panic on my machine.  I had to reconstruct it from
> > > OCR, the machine has no serial port, sorry if there are typos.
> > 
> > boot crash can be helpful for such machines

Oh nice, thanks.

> > > [...]
> > > 
> > > db_enter() at db_enter+Oxa
> > > panic(81db24fb) at panic+0x12f
> > > task del(0,810633e0) at task_del+Oxa8
> > > edp_panel vdd_on(81063128) at edp_panel_vdd_on+0x6a
> > > intel_dp_aux_xfer(81063128, 82512a20,4, 
> > > 82512400,2,0) at intel_dp_aux_xfer+0x18b
> > > intel_dp_aux_transfer(810631e8, 82512a88) at 
> > > intel_dp_aux_transfer+0x183
> > > drm_dp_dpcd_access(810631e8,9,0,8106313a, 1) at 
> > > drm_dp_dpcd_access+Oxa9
> > > drm_dp_dpcd_read(810631e8,0,8106313a, f) at 
> > > drm_dp_dpcd_read+0x61
> > > intel_dp_read_dpcd(81063128) at intel_dp_read_dpcd+0x45
> > > intel_dp_init_connector(81063000, 81064000) at 
> > > intel_dp_init_connector+0x988
> > > intel_ddi_init(80272000,0) at intel_ddi_init+0x454
> > > intel_modeset_init(80272000) at intel_modeset_init+0x1c9f
> > > i915_driver_probe(80272000, 82052f98) at 
> > > i915_driver_probe+0x7df
> > > inteldrm_attachhook(80272000) at inteldrm_attachhook+0x46
> > > end trace frame: Ox82512700, count: 0
> > > 
> > > From the backtrace, I gather the following:
> > > 
> > > edp_panel_vdd_on() calls clear_delayed_work() which is just a macro
> > 
> > cancel_delayed_work()

whoops

> > > that calls task_del().  And for whatever reason the taskq passed to
> > > task_del() is NULL.  Maybe there is a missing INIT_DELAYED_WORK() call
> > > somewhere prior to this point?
> > 
> > the call to that is in
> > INIT_DELAYED_WORK(_dp->panel_vdd_work, edp_panel_vdd_work);
> > but tq doesn't get set until work is scheduled as there are interfaces
> > to pick a tq when scheduling work.
> > 
> > So perhaps you want something like this to catch the cases where work is
> > cancelled before it is scheduled.
> 
> Yeah, I think that makes sense.
> 
> ok kettenis@

This patch fixes the panic, running with it now.

ok cheloha@

Caveat: my confidence in my understanding of these interfaces is
pretty low.

-Scott

intel(4): edp_panel_vdd_on calls task_del(9) with NULL taskq

[Scott Cheloha]

Hi,

On a hunch I added additional parameter checks to task_add(9) and
task_del(9) and caught intel(4) doing something strange.

The patch is straightforward: check that the taskq pointer tq is not
NULL.  In the current code we return early if a flag is set or cleared
in the task w, in which case we don't catch bogus taskq inputs, which
is why the machine boots fine without the extra checks.

The patch:

Index: kern_task.c
===
RCS file: /cvs/src/sys/kern/kern_task.c,v
retrieving revision 1.31
diff -u -p -r1.31 kern_task.c
--- kern_task.c 1 Aug 2020 08:40:20 -   1.31
+++ kern_task.c 5 May 2021 21:29:08 -
@@ -354,6 +354,9 @@ task_add(struct taskq *tq, struct task *
 {
int rv = 0;
 
+   if (tq == NULL)
+   panic("%s: NULL taskq", __func__);
+
if (ISSET(w->t_flags, TASK_ONQUEUE))
return (0);
 
@@ -378,6 +381,9 @@ int
 task_del(struct taskq *tq, struct task *w)
 {
int rv = 0;
+
+   if (tq == NULL)
+   panic("%s: NULL taskq", __func__);
 
if (!ISSET(w->t_flags, TASK_ONQUEUE))
return (0);

And here is the panic on my machine.  I had to reconstruct it from
OCR, the machine has no serial port, sorry if there are typos.

panic: task_del: NULL taskq
Stopped at db_enter+0xa: popq %rbp
TIDPID  UID PRFLAGSPFLAGS  CPU  COMMAND
 513524  448830 Ox14000 0x2003  update
 352928  824020 0x14000 0x2002  cleaner
 382195  660350 Ox14000 0x2001  reaper
...
db_enter() at db_enter+Oxa
panic(81db24fb) at panic+0x12f
task del(0,810633e0) at task_del+Oxa8
edp_panel vdd_on(81063128) at edp_panel_vdd_on+0x6a
intel_dp_aux_xfer(81063128, 82512a20,4, 82512400,2,0) 
at intel_dp_aux_xfer+0x18b
intel_dp_aux_transfer(810631e8, 82512a88) at 
intel_dp_aux_transfer+0x183
drm_dp_dpcd_access(810631e8,9,0,8106313a, 1) at 
drm_dp_dpcd_access+Oxa9
drm_dp_dpcd_read(810631e8,0,8106313a, f) at 
drm_dp_dpcd_read+0x61
intel_dp_read_dpcd(81063128) at intel_dp_read_dpcd+0x45
intel_dp_init_connector(81063000, 81064000) at 
intel_dp_init_connector+0x988
intel_ddi_init(80272000,0) at intel_ddi_init+0x454
intel_modeset_init(80272000) at intel_modeset_init+0x1c9f
i915_driver_probe(80272000, 82052f98) at i915_driver_probe+0x7df
inteldrm_attachhook(80272000) at inteldrm_attachhook+0x46
end trace frame: Ox82512700, count: 0

>From the backtrace, I gather the following:

edp_panel_vdd_on() calls clear_delayed_work() which is just a macro
that calls task_del().  And for whatever reason the taskq passed to
task_del() is NULL.  Maybe there is a missing INIT_DELAYED_WORK() call
somewhere prior to this point?

And yes, I know, this isn't a bug in the code as-is, but I'm putting
this on bugs@ because I'm pretty certain the taskq shouldn't be NULL.
It "works" without the additional checks, yes, but something is off.

My dmesg is attached.

Happy to provide more detail, reproduce it, etc.

CC dlg@: Maybe there is a discussion to be had about always entering
the taskq mutex during task_add() and task_del() to catch this problem
in the future?

-Scott

OpenBSD 6.9-current (GENERIC.MP) #0: Tue May  4 14:43:41 CDT 2021
ssc@jetsam.local:/usr/src/sys/arch/amd64/compile/GENERIC.MP
real mem = 16895528960 (16112MB)
avail mem = 16368230400 (15609MB)
random: good seed from bootblocks
mpath0 at root
scsibus0 at mpath0: 256 targets
mainbus0 at root
bios0 at mainbus0: SMBIOS rev. 3.0 @ 0x9f03b000 (63 entries)
bios0: vendor LENOVO version "N23ET59W (1.34 )" date 11/08/2018
bios0: LENOVO 20KHCTO1WW
acpi0 at bios0: ACPI 5.0
acpi0: sleep states S0 S3 S4 S5
acpi0: tables DSDT FACP SSDT SSDT TPM2 UEFI SSDT SSDT HPET APIC MCFG ECDT SSDT 
SSDT BOOT BATB SSDT SSDT SSDT LPIT WSMT SSDT SSDT SSDT DBGP DBG2 MSDM DMAR NHLT 
ASF! FPDT UEFI
acpi0: wakeup devices GLAN(S4) XHC_(S3) XDCI(S4) HDAS(S4) RP01(S4) PXSX(S4) 
RP02(S4) PXSX(S4) PXSX(S4) RP04(S4) PXSX(S4) RP05(S4) PXSX(S4) RP06(S4) 
PXSX(S4) RP07(S4) [...]
acpitimer0 at acpi0: 3579545 Hz, 24 bits
acpihpet0 at acpi0: 2399 Hz
acpimadt0 at acpi0 addr 0xfee0: PC-AT compat
cpu0 at mainbus0: apid 0 (boot processor)
cpu0: Intel(R) Core(TM) i7-8650U CPU @ 1.90GHz, 1791.41 MHz, 06-8e-0a
cpu0: 
FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,CFLUSH,DS,ACPI,MMX,FXSR,SSE,SSE2,SS,HTT,TM,PBE,SSE3,PCLMUL,DTES64,MWAIT,DS-CPL,VMX,SMX,EST,TM2,SSSE3,SDBG,FMA3,CX16,xTPR,PDCM,PCID,SSE4.1,SSE4.2,x2APIC,MOVBE,POPCNT,DEADLINE,AES,XSAVE,AVX,F16C,RDRAND,NXE,PAGE1GB,RDTSCP,LONG,LAHF,ABM,3DNOWP,PERF,ITSC,FSGSBASE,TSC_ADJUST,SGX,BMI1,HLE,AVX2,SMEP,BMI2,ERMS,INVPCID,RTM,MPX,RDSEED,ADX,SMAP,CLFLUSHOPT,PT,SRBDS_CTRL,MD_CLEAR,TSXFA,IBRS,IBPB,STIBP,L1DF,SSBD,SENSOR,ARAT,XSAVEOPT,XSAVEC,XGETBV1,XSAVES,MELTDOWN
cpu0: 256KB 64b/line 8-way L2 cache
cpu0: 

amd64-current: inteldrm: witness(4) warnings during boot

[Scott Cheloha]

Yesterday I enabled witness(4) to debug something unrelated and
started seeing traces during boot.

My kernel is up-to-date as of yesterday night.  My inteldrm firmware
is also up-to-date.

The traces appear during every cold boot.  Here is the most recent set
from my last reboot, plucked from the dmesg:

root on sd0a (847a92f1384e1964.a) swap on sd0b dump on sd0b
witness: lock order reversal:
 1st 0xfd844b4aad98 i915_active (>mutex)
 2nd 0x8026ff10 vmlk (>mutex)
lock order ">mutex"(rwlock) -> ">mutex"(rwlock) first seen at:
#0  witness_checkorder+0x466
#1  rw_enter+0x67
#2  i915_active_acquire+0x47
#3  i915_vma_pin+0x2c4
#4  i915_ggtt_pin+0x62
#5  intel_gt_init+0xb9
#6  i915_gem_init+0xa3
#7  i915_driver_probe+0x821
#8  inteldrm_attachhook+0x45
#9  config_process_deferred_mountroot+0x6b
#10 main+0x723
lock order ">mutex"(rwlock) -> ">mutex"(rwlock) first seen at:
#0  witness_checkorder+0x466
#1  rw_enter+0x67
#2  i915_vma_pin+0x250
#3  i915_ggtt_pin+0x62
#4  intel_ring_pin+0x65
#5  __intel_context_active+0x33
#6  i915_active_acquire+0x85
#7  __intel_context_do_pin+0x3b
#8  intel_engines_init+0x4e1
#9  intel_gt_init+0x130
#10 i915_gem_init+0xa3
#11 i915_driver_probe+0x821
#12 inteldrm_attachhook+0x45
#13 config_process_deferred_mountroot+0x6b
#14 main+0x723
witness: acquiring duplicate lock of same type: ">mutex"
 1st i915_active
 2nd i915_active
Starting stack trace...
witness_checkorder(80eb23c8,9,0) at witness_checkorder+0x809
rw_enter(80eb23b8,11) at rw_enter+0x67
i915_active_acquire(80eb23b0) at i915_active_acquire+0x47
__intel_context_active(fd844b4aad80) at __intel_context_active+0x4d
i915_active_acquire(fd844b4aad80) at i915_active_acquire+0x85
__intel_context_do_pin(fd844b4aacb0) at __intel_context_do_pin+0x3b
intel_engines_init(80272060) at intel_engines_init+0x4e1
intel_gt_init(80272060) at intel_gt_init+0x130
i915_gem_init(8026d000) at i915_gem_init+0xa3
i915_driver_probe(8026d000,82029be8) at i915_driver_probe+0x821
inteldrm_attachhook(8026d000) at inteldrm_attachhook+0x45
config_process_deferred_mountroot() at config_process_deferred_mountroot+0x6b
main(0) at main+0x723
end trace frame: 0x0, count: 244
End of stack trace.
inteldrm0: 2560x1440, 32bpp
wsdisplay0 at inteldrm0 mux 1: console (std, vt100 emulation), using wskbd0
wsdisplay0: screen 1-5 added (std, vt100 emulation)
iwm0: hw rev 0x230, fw ver 34.0.1, address 98:3b:8f:ef:6b:ef
witness: acquiring duplicate lock of same type: ">mutex"
 1st wakeref.mutex
 2nd wakeref.mutex
Starting stack trace...
witness_checkorder(80272500,9,0) at witness_checkorder+0x809
rw_enter_write(802724f0) at rw_enter_write+0x43
__intel_wakeref_get_first(802724e8) at __intel_wakeref_get_first+0x28
__engine_unpark(8086c180) at __engine_unpark+0x46
__intel_wakeref_get_first(8086c180) at __intel_wakeref_get_first+0x4a
i915_active_acquire_preallocate_barrier(fd83d3bf5d88,8086c000) at 
i915_active_acquire_preallocate_barrier+0xa8
__intel_context_do_pin(fd83d3bf5cb8) at __intel_context_do_pin+0xa6
i915_gem_do_execbuffer(8026d078,81364000,8000451ff000,8135a800,0)
 at i915_gem_do_execbuffer+0x288f
i915_gem_execbuffer2_ioctl(8026d078,8000451ff000,81364000) 
at i915_gem_execbuffer2_ioctl+0x1da
drm_do_ioctl(8026d078,100,80406469,8000451ff000) at 
drm_do_ioctl+0x274
drmioctl(15700,80406469,8000451ff000,3,8000452c2f98) at drmioctl+0xdc
VOP_IOCTL(fd83d1e435c8,80406469,8000451ff000,3,fd8450fa8480,8000452c2f98)
 at VOP_IOCTL+0x55
vn_ioctl(fd83d22725f8,80406469,8000451ff000,8000452c2f98) at 
vn_ioctl+0x75
sys_ioctl(8000452c2f98,8000451ff110,8000451ff170) at sys_ioctl+0x2d4
syscall(8000451ff1e0) at syscall+0x389
Xsyscall() at Xsyscall+0x128
end of kernel
end trace frame: 0x7f7ca3a0, count: 241
End of stack trace.
witness: acquiring duplicate lock of same type: ">lock"
 1st >lock
 2nd >lock
Starting stack trace...
witness_checkorder(8147a628,9,0) at witness_checkorder+0x809
mtx_enter(8147a618) at mtx_enter+0x3c
i915_active_ref(814a2bf0,81477000,8147a2e8) at 
i915_active_ref+0x1fd
i915_vma_move_to_active(814a2af8,8147a2e8,8018) at 
i915_vma_move_to_active+0x5c
i915_gem_do_execbuffer(8026d078,81364000,8000451ff000,81483000,0)
 at i915_gem_do_execbuffer+0x323a
i915_gem_execbuffer2_ioctl(8026d078,8000451ff000,81364000) 
at i915_gem_execbuffer2_ioctl+0x1da
drm_do_ioctl(8026d078,100,80406469,8000451ff000) at 
drm_do_ioctl+0x274
drmioctl(15700,80406469,8000451ff000,3,8000452c2f98) at drmioctl+0xdc
VOP_IOCTL(fd83d1e435c8,80406469,8000451ff000,3,fd8450fa8480,8000452c2f98)
 at VOP_IOCTL+0x55
vn_ioctl(fd83d22725f8,80406469,8000451ff000,8000452c2f98) at 
vn_ioctl+0x75

Re: ntpd(8) adds time since epoch to system clock

[Scott Cheloha]

> On Aug 7, 2020, at 11:28 AM, Otto Moerbeek  wrote:
> 
> On Fri, Aug 07, 2020 at 11:17:18AM -0500, Scott Cheloha wrote:
> 
>> On Mon, Aug 05, 2069 at 09:33:05AM +, Toby Betts wrote:
>>>> Synopsis:  ntpd(8) adds time since epoch to system clock
>>>> Category:  system
>>>> Environment:
>>> System  : OpenBSD 6.6
>>> Details : OpenBSD 6.6 (GENERIC.MP) #372: Sat Oct 12 10:56:27 MDT 
>>> 2019
>>>  
>>> dera...@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
>>> 
>>> Architecture: OpenBSD.amd64
>>> Machine : amd64
>>>> Description:
>>> After rebooting a VM, ntpd(8) adjusted the system clock to 2069-08-04.
>>> The reboot command was given at approximately 2019-10-18 23:34:49 UTC,
>>> which is about 1571441689 seconds since the UNIX epoch, 1970-01-01.
>>> According to /var/log/daemon, stepping the clock from 2019-10-18 to
>>> 2069-08-04 is 1571441749.182430 seconds, which is approximately the
>>> same number of seconds as the system time on the VM when ntpd(8) was
>>> started again after the reboot.
>>> 
>>> In other words when ntpd(8) started, it set the system clock to double the
>>> current time in seconds since 1970.
>>> 
>>> Output of /var/log/daemon:
>>> 
>>> Oct 18 22:53:06 obsd ntpd[96201]: creating new /var/db/ntpd.drift
>>> Oct 18 22:53:06 obsd ntpd[3505]: ntp engine ready
>>> Oct 18 22:53:08 obsd ntpd[96201]: set local clock to Fri Oct 18 22:53:08 
>>> UTC 2019 (offset 1.652045s)
>>> Oct 18 22:53:08 obsd savecore: no core dump
>>> Oct 18 22:53:09 obsd ntpd[3505]: constraint reply from 172.217.3.196: 
>>> offset -0.075150
>>> Oct 18 22:53:28 obsd ntpd[3505]: peer 47.190.36.230 now valid
>>> Oct 18 22:53:29 obsd ntpd[3505]: peer 3.15.245.6 now valid
>>> Oct 18 22:53:30 obsd ntpd[3505]: peer 162.159.200.1 now valid
>>> Oct 18 22:53:30 obsd ntpd[3505]: peer 184.105.182.16 now valid
>>> Oct 18 22:53:31 obsd ntpd[3505]: peer 198.50.238.163 now valid
>>> Oct 18 22:58:41 obsd ntpd[3505]: clock is now synced
>>> Oct 18 22:58:41 obsd ntpd[3505]: constraint reply from 172.217.3.196: 
>>> offset -0.924238
>>> Oct 18 23:03:44 obsd ntpd[3505]: peer 3.15.245.6 now invalid
>>> Oct 18 23:04:04 obsd ntpd[3505]: peer 104.131.139.195 now valid
>>> Oct 18 23:19:12 obsd ntpd[39106]: adjusting clock frequency by -20.378477 
>>> to -20.378477ppm
>>> 
>>> [ reboot issued approximately here ]
>>> 
>>> Oct 18 23:35:12 obsd ntpd[39106]: adjusting clock frequency by -0.737827 to 
>>> -21.116304ppm
>>> Oct 18 23:35:53 obsd ntpd[35750]: ntp engine ready
>>> Aug  4 23:11:42 obsd ntpd[79447]: set local clock to Sun Aug  4 23:11:42 
>>> UTC 2069 (offset 1571441749.182430s)
>>> Aug  4 23:11:42 obsd savecore: no core dump
>>> Aug  4 23:11:43 obsd ntpd[35750]: constraint reply from 172.217.3.196: 
>>> offset -1571441748.432712
>>> Aug  4 23:12:02 obsd ntpd[35750]: peer 45.79.36.123 now valid
>>> Aug  4 23:12:03 obsd ntpd[35750]: peer 162.159.200.1 now valid
>>> Aug  4 23:12:03 obsd ntpd[35750]: peer 162.159.200.1 now valid
>>> Aug  4 23:12:04 obsd ntpd[35750]: peer 103.105.51.156 now valid
>>> Aug  4 23:12:08 obsd ntpd[35750]: peer 199.101.100.221 now valid
>>> Aug  4 23:13:02 obsd ntpd[23365]: adjusting local clock by 
>>> -1571441747.612037s
>>> Aug  4 23:16:16 obsd ntpd[23365]: adjusting local clock by 
>>> -1571441746.642918s
>>> Aug  4 23:17:19 obsd ntpd[23365]: adjusting local clock by 
>>> -1571441746.326408s
>>> Aug  4 23:21:43 obsd ntpd[23365]: adjusting local clock by 
>>> -1571441744.999186s
>>> Aug  4 23:22:14 obsd ntpd[23365]: adjusting local clock by 
>>> -1571441744.843526s
>>> Aug  4 23:26:29 obsd ntpd[23365]: adjusting local clock by 
>>> -1571441743.563666s
>>> Aug  4 23:27:35 obsd ntpd[23365]: adjusting local clock by 
>>> -1571441743.233665s
>>> Aug  4 23:28:05 obsd ntpd[23365]: adjusting local clock by 
>>> -1571441743.082044s
>>> Aug  4 23:32:22 obsd ntpd[23365]: adjusting local clock by 
>>> -1571441741.788132s
>>> Aug  4 23:33:23 obsd ntpd[35750]: peer 45.79.36.123 now invalid
>>> Aug  4 23:33:46 obsd ntpd[35750]: peer 72.87.88.202 now valid
>>> Aug  4 23:34:43 obsd ntpd[23365]: adjusting local clock by 
>>> -1571441741.077493s
>>> Aug  4 23:37:26 obsd ntpd[2336

Re: ntpd(8) adds time since epoch to system clock

[Scott Cheloha]

On Mon, Aug 05, 2069 at 09:33:05AM +, Toby Betts wrote:
> >Synopsis:ntpd(8) adds time since epoch to system clock
> >Category:system
> >Environment:
>   System  : OpenBSD 6.6
>   Details : OpenBSD 6.6 (GENERIC.MP) #372: Sat Oct 12 10:56:27 MDT 
> 2019
>
> dera...@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
> 
>   Architecture: OpenBSD.amd64
>   Machine : amd64
> >Description:
>   After rebooting a VM, ntpd(8) adjusted the system clock to 2069-08-04.
>   The reboot command was given at approximately 2019-10-18 23:34:49 UTC,
>   which is about 1571441689 seconds since the UNIX epoch, 1970-01-01.
>   According to /var/log/daemon, stepping the clock from 2019-10-18 to
>   2069-08-04 is 1571441749.182430 seconds, which is approximately the
>   same number of seconds as the system time on the VM when ntpd(8) was
>   started again after the reboot.
> 
> In other words when ntpd(8) started, it set the system clock to double the
> current time in seconds since 1970.
> 
> Output of /var/log/daemon:
> 
> Oct 18 22:53:06 obsd ntpd[96201]: creating new /var/db/ntpd.drift
> Oct 18 22:53:06 obsd ntpd[3505]: ntp engine ready
> Oct 18 22:53:08 obsd ntpd[96201]: set local clock to Fri Oct 18 22:53:08 UTC 
> 2019 (offset 1.652045s)
> Oct 18 22:53:08 obsd savecore: no core dump
> Oct 18 22:53:09 obsd ntpd[3505]: constraint reply from 172.217.3.196: offset 
> -0.075150
> Oct 18 22:53:28 obsd ntpd[3505]: peer 47.190.36.230 now valid
> Oct 18 22:53:29 obsd ntpd[3505]: peer 3.15.245.6 now valid
> Oct 18 22:53:30 obsd ntpd[3505]: peer 162.159.200.1 now valid
> Oct 18 22:53:30 obsd ntpd[3505]: peer 184.105.182.16 now valid
> Oct 18 22:53:31 obsd ntpd[3505]: peer 198.50.238.163 now valid
> Oct 18 22:58:41 obsd ntpd[3505]: clock is now synced
> Oct 18 22:58:41 obsd ntpd[3505]: constraint reply from 172.217.3.196: offset 
> -0.924238
> Oct 18 23:03:44 obsd ntpd[3505]: peer 3.15.245.6 now invalid
> Oct 18 23:04:04 obsd ntpd[3505]: peer 104.131.139.195 now valid
> Oct 18 23:19:12 obsd ntpd[39106]: adjusting clock frequency by -20.378477 to 
> -20.378477ppm
> 
> [ reboot issued approximately here ]
> 
> Oct 18 23:35:12 obsd ntpd[39106]: adjusting clock frequency by -0.737827 to 
> -21.116304ppm
> Oct 18 23:35:53 obsd ntpd[35750]: ntp engine ready
> Aug  4 23:11:42 obsd ntpd[79447]: set local clock to Sun Aug  4 23:11:42 UTC 
> 2069 (offset 1571441749.182430s)
> Aug  4 23:11:42 obsd savecore: no core dump
> Aug  4 23:11:43 obsd ntpd[35750]: constraint reply from 172.217.3.196: offset 
> -1571441748.432712
> Aug  4 23:12:02 obsd ntpd[35750]: peer 45.79.36.123 now valid
> Aug  4 23:12:03 obsd ntpd[35750]: peer 162.159.200.1 now valid
> Aug  4 23:12:03 obsd ntpd[35750]: peer 162.159.200.1 now valid
> Aug  4 23:12:04 obsd ntpd[35750]: peer 103.105.51.156 now valid
> Aug  4 23:12:08 obsd ntpd[35750]: peer 199.101.100.221 now valid
> Aug  4 23:13:02 obsd ntpd[23365]: adjusting local clock by -1571441747.612037s
> Aug  4 23:16:16 obsd ntpd[23365]: adjusting local clock by -1571441746.642918s
> Aug  4 23:17:19 obsd ntpd[23365]: adjusting local clock by -1571441746.326408s
> Aug  4 23:21:43 obsd ntpd[23365]: adjusting local clock by -1571441744.999186s
> Aug  4 23:22:14 obsd ntpd[23365]: adjusting local clock by -1571441744.843526s
> Aug  4 23:26:29 obsd ntpd[23365]: adjusting local clock by -1571441743.563666s
> Aug  4 23:27:35 obsd ntpd[23365]: adjusting local clock by -1571441743.233665s
> Aug  4 23:28:05 obsd ntpd[23365]: adjusting local clock by -1571441743.082044s
> Aug  4 23:32:22 obsd ntpd[23365]: adjusting local clock by -1571441741.788132s
> Aug  4 23:33:23 obsd ntpd[35750]: peer 45.79.36.123 now invalid
> Aug  4 23:33:46 obsd ntpd[35750]: peer 72.87.88.202 now valid
> Aug  4 23:34:43 obsd ntpd[23365]: adjusting local clock by -1571441741.077493s
> Aug  4 23:37:26 obsd ntpd[23365]: adjusting local clock by -1571441740.260640s
> Aug  4 23:40:41 obsd ntpd[23365]: adjusting local clock by -1571441739.281630s
> Aug  4 23:42:49 obsd ntpd[23365]: adjusting local clock by -1571441738.634681s
> Aug  4 23:43:55 obsd ntpd[23365]: adjusting local clock by -1571441738.304680s
> Aug  4 23:44:28 obsd ntpd[23365]: adjusting local clock by -1571441738.139680s
> Aug  4 23:45:35 obsd ntpd[23365]: adjusting local clock by -1571441737.800824s
> Aug  4 23:47:07 obsd ntpd[23365]: adjusting local clock by -1571441737.340824s
> Aug  4 23:47:41 obsd ntpd[23365]: adjusting local clock by -1571441737.170823s
> Aug  4 23:49:20 obsd ntpd[23365]: adjusting local clock by -1571441736.675189s
> Aug  4 23:52:29 obsd ntpd[23365]: adjusting local clock by -1571441735.717282s
> Aug  4 23:56:39 obsd ntpd[23365]: adjusting local clock by -1571441734.467036s
> Aug  4 23:58:16 obsd ntpd[23365]: adjusting local clock by -1571441733.977244s
> Aug  5 00:01:30 obsd ntpd[23365]: adjusting local clock by -1571441733.007243s
> Aug  5 00:02:36 obsd ntpd[23365]: adjusting local 

Re: getdelim and O_NONBLOCK

[Scott Cheloha]

On Fri, Mar 29, 2019 at 08:19:12PM +0100, Martijn van Duren wrote:
> Running getdelim on a nonblocking socket results in data loss of the 
> first part of the message if the said message is sent in chunks.
> Code below shows how to repeat.
> 
> POSIX states the following:
> For the conditions under which the getdelim() and getline() functions
> shall fail and may fail, refer to fgetc.
> 
> And for fgetc:
> [EAGAIN]
> The O_NONBLOCK flag is set for the file descriptor underlying stream
> and the thread would be delayed in the fgetc() operation
> 
> This to me reads that the first call should retain the data in the
> buffer and the second call should return the entire sentence.
> I also ran the code on Alpine Linux (musl libc) and Linux Mint (glibc).
> Musl behaves just like us and glibc returns the first part of the
> sentence without the delimiter (returning a positive value, indicating
> there's no error so far), which is a violation of the specs, which
> states that the data returned contains the newline.
> 
> I also looked at the getdelim.c code, but I don't have the knowledge/
> time to send a diff at this time. But maybe someone has some useful
> input on this.

Hmmm, interesting corner case.  Clobbering the data without ever
telling the caller about it is bad.

One solution is something like: check in the error case if we read
anything, and if so then "put it all back" a la ungetc(3).

I don't think we can just store what we read in the buffer across
calls.  The only state we're given when we call getdelim(3) is the
size of the buffer, which is at least buflen.  But the spec says
nothing about the caller using the same buffer between calls: even
if that's idiomatic we can't rely on the application to do that for us.

I'm beat, so this isn't happening immediately, but I think if we
refactored __srefill() and added something like __sappend() to append
new data to the FILE's buffer (growing it if necessary) and then
changed the getdelim(3) logic to __sappend() if fp->_r > 0 and the
delimiter is not in the buffer, we'd... have done what I just
described.  But I need to look more closely at stdio to figure out
how... and to make sure I'm not talking nonsense.

We sort of do something similar in fgetln(3) already, but we use an
auxiliary buffer.

Maybe of note is that our fgetc(3) docs claim C89 behavior, not all
the additional stuff POSIX.1-2008 specifies.  Which doesn't make
our getdelim(3) non-conforming per se, but it makes it difficult
for the application developer to even know that this case is
possible.

Re: Bug in OpenBSD 6.3 /usr/bin/wc

[Scott Cheloha]

On Thu, Sep 27, 2018 at 05:09:22PM -0500, Scott Cheloha wrote:
> > On Sep 27, 2018, at 10:26, Todd C. Miller  wrote:
> > 
> >> On Thu, 27 Sep 2018 16:19:46 +0100, Dave Hines wrote:
> >> 
> >> Oops - my patch contained a bug (though it worked on my machine).
> >> Here is a corrected patch for /usr/src/usr.bin/wc/wc.c
> > 
> > That fix looks correct to me.
> 
> Ditto, works here. I will commit tonight if someone else doesn't
> chime in.
> 
> (ok cheloha@ if someone else commits first)

Committed, thanks!

Re: Bug in OpenBSD 6.3 /usr/bin/wc

[Scott Cheloha]

> On Sep 27, 2018, at 10:26, Todd C. Miller  wrote:
> 
>> On Thu, 27 Sep 2018 16:19:46 +0100, Dave Hines wrote:
>> 
>> Oops - my patch contained a bug (though it worked on my machine).
>> Here is a corrected patch for /usr/src/usr.bin/wc/wc.c
> 
> That fix looks correct to me.

Ditto, works here. I will commit tonight if someone else doesn't
chime in.

(ok cheloha@ if someone else commits first)

Re: apmd(8): poll timer miscalculation

[Scott Cheloha]

On Thu, Jun 07, 2018 at 11:27:34AM +, sunil+b...@nimmagadda.net wrote:
> >Synopsis:apmd(8) poll timer off by 10x
> >Category:system
> >Environment:
>   System  : OpenBSD 6.3
>   Details : OpenBSD 6.3-current (GENERIC.MP) #54: Wed May 30 23:03:50 
> MDT 2018
>
> dera...@amd64.openbsd.org:/usr/src/sys/arch/amd64/compile/GENERIC.MP
> 
>   Architecture: OpenBSD.amd64
>   Machine : amd64
> >Description:
> With apmd_flags="-Az10", expected apmd(8) to suspend when
> battery is at 10%, however, it didn't check in time and
> laptop ran of out power.
> >How-To-Repeat:
> Disconnect A/C adapter and run with -z percent greater
> than current estimated battery life reported by apm(8);
> poll every minute, for example...
>   # rcctl stop apmd
>   # apmd -A -z90 -t60
> should suspend in a minute, however, it suspends after 10
> minutes.
> >Fix:
>   The following diff...
> 
> 1. Provides a dedicated timer that fires every 10 seconds
> instead of relying on EVFILT_READ freqency.
> 
> 2. Increments a counter and checks against timeout value,
> if it exceeds, invokes auto-action.
> 
> 3. Wraps a few long lines that exceed 80 cols upon code
> shuffle.

I don't think we need to introduce an additional timer, or do so much
code shufflin' here, to fix your issue.  The problem seems to be that
apmtimeout is incremented once per iteration but must meet or exceed
ts.tv_sec to trigger a status check, so the period for battery status
checks is at least n^2 seconds.

I'm pretty sure this was unintentional, though it makes it unlikely
that apmd will catch a low battery percentage and suspend the machine
before the battery is totally exhausted.  Especially since, by default,
n = 600.

Here's a minimal diff that checks if we timed out on return from kevent.
There's additional cleanup that this change implies, but I've left it out
for the moment.

Of note is that an event for either of the descriptors resets the
timeout, regardless of how long it's been since we checked the battery
status: this is effectively the current behavior.  If people want, we
can add logic to decrement the maximum timeout accordingly on each
iteration and reset it when kevent truly times out.  This sounds closer
to what the manpage advertises for the -t option.

Caveat: I'm unfamiliar with apmd(8) and I don't have time just this
second scour the change log to figure out why the behavior is what it
is now.  Someone more familiar with the code will need to corroborate
what I've said and the attached diff.

That said, feel free to try this diff in the meantime.  Does this work
for you?

Anyone more familiar with apmd(8) wanna chime in here?

--
Scott Cheloha

Index: usr.sbin/apmd/apmd.c
===
RCS file: /cvs/src/usr.sbin/apmd/apmd.c,v
retrieving revision 1.81
diff -u -p -r1.81 apmd.c
--- usr.sbin/apmd/apmd.c15 Oct 2017 15:14:49 -  1.81
+++ usr.sbin/apmd/apmd.c7 Jun 2018 20:26:11 -
@@ -488,7 +488,7 @@ main(int argc, char *argv[])
if ((rv = kevent(kq, NULL, 0, ev, 1, )) < 0)
break;
 
-   if (apmtimeout >= ts.tv_sec) {
+   if (rv == 0) {
apmtimeout = 0;
 
/* wakeup for timeout: take status */

openssl: s_time needs dns pledge promise

[Scott Cheloha]

Hi,

The following (and similar invocations) gets SIGABRT'd:

openssl s_time -connect openbsd.org:443

BIO_set_conn_hostname(3), or whatever BIO_ctrl(3) is doing
underneath, tries to resolve your target host and the process
gets signaled when it enters socket(2).

Adding "dns" to the pledge(2) promise corrects this.

It looks like this has been broken since ~2015 but I have no
release machines handy to confirm.

--
Scott Cheloha

Index: usr.bin/openssl/s_time.c
===
RCS file: /cvs/src/usr.bin/openssl/s_time.c,v
retrieving revision 1.17
diff -u -p -r1.17 s_time.c
--- usr.bin/openssl/s_time.c20 Jan 2017 08:57:12 -  1.17
+++ usr.bin/openssl/s_time.c1 Nov 2017 23:30:23 -
@@ -254,7 +254,7 @@ s_time_main(int argc, char **argv)
int ver;
 
if (single_execution) {
-   if (pledge("stdio rpath inet", NULL) == -1) {
+   if (pledge("stdio rpath inet dns", NULL) == -1) {
perror("pledge");
exit(1);
}

Re: write.2: caveats: write(2) returns zero?

[Scott Cheloha]

> On Sep 17, 2017, at 4:53 AM, Marc Espie <es...@nerim.net> wrote:
> 
> On Sat, Sep 16, 2017 at 10:25:19PM -0500, Scott Cheloha wrote:
>> Hi,
>> 
>> [...]
>> 
>> --
>> Scott Cheloha
>> 
>> Index: lib/libc/sys/write.2
>> ===
>> RCS file: /cvs/src/lib/libc/sys/write.2,v
>> retrieving revision 1.39
>> diff -u -p -r1.39 write.2
>> --- lib/libc/sys/write.2 5 Feb 2015 02:33:09 -   1.39
>> +++ lib/libc/sys/write.2 17 Sep 2017 03:02:57 -
>> @@ -311,7 +311,7 @@ function call appeared in
>> Error checks should explicitly test for \-1.
>> Code such as
>> .Bd -literal -offset indent
>> -while ((nr = write(fd, buf, sizeof(buf))) > 0)
>> +while ((nw = write(fd, buf, sizeof(buf))) > 0)
>> .Ed
>> .Pp
>> is not maximally portable, as some platforms allow for
>> @@ -325,5 +325,5 @@ and
>> may appear as a negative number distinct from \-1.
>> Proper loops should use
>> .Bd -literal -offset indent
>> -while ((nr = write(fd, buf, sizeof(buf))) != -1 && nr != 0)
>> +while ((nw = write(fd, buf, sizeof(buf))) != -1 && nw == sizeof(buf))
>> .Ed
> 
> Well, that's not okay either, because nw == sizeof(buf) will only make
> sense for file-based fds.

Ah, okay.  So my third question was about partial writes.

I left it out because I figured that we could just say explicitly
that the examples did not cover partial writes if need be.

At least, I think that's what you mean when you say that '== sizeof(buf)'
only makes sense for file-based fds.

> I'm for either scraping the example altogether or writing a proper
> one, which would mean embedding any version of safe_write in the
> man page.

Could you point to an example of safe_write in the tree that covers
what you're looking for?  Is it akin to writeall() in signify(1) or
atomicio() for nc(1)?

--
Scott Cheloha

write.2: caveats: write(2) returns zero?

[Scott Cheloha]

Hi,

The second example in the write(2) CAVEATS section is identical to
the corresponding example in the read(2) page:

while ((nr = write(fd, buf, sizeof(buf))) != -1 && nr != 0)

read(2) returns 0 on EOF, but that logic is inapplicable to write(2).

I'm not totally sure what the correct code should be but attached is
my best guess.

Also, if "nr" is for "Number Read", because this is the write(2)
page, would "nw" be better?

--
Scott Cheloha

Index: lib/libc/sys/write.2
===
RCS file: /cvs/src/lib/libc/sys/write.2,v
retrieving revision 1.39
diff -u -p -r1.39 write.2
--- lib/libc/sys/write.25 Feb 2015 02:33:09 -   1.39
+++ lib/libc/sys/write.217 Sep 2017 03:02:57 -
@@ -311,7 +311,7 @@ function call appeared in
 Error checks should explicitly test for \-1.
 Code such as
 .Bd -literal -offset indent
-while ((nr = write(fd, buf, sizeof(buf))) > 0)
+while ((nw = write(fd, buf, sizeof(buf))) > 0)
 .Ed
 .Pp
 is not maximally portable, as some platforms allow for
@@ -325,5 +325,5 @@ and
 may appear as a negative number distinct from \-1.
 Proper loops should use
 .Bd -literal -offset indent
-while ((nr = write(fd, buf, sizeof(buf))) != -1 && nr != 0)
+while ((nw = write(fd, buf, sizeof(buf))) != -1 && nw == sizeof(buf))
 .Ed

Re: ksh.1: two typos

[Scott Cheloha]

> On Aug 18, 2017, at 1:18 AM, Jason McIntyre <j...@kerhand.co.uk> wrote:
> 
> [...]
> 
>> --
>> Scott Cheloha
>> 
>> Index: bin/ksh/ksh.1
>> ===
>> RCS file: /cvs/src/bin/ksh/ksh.1,v
>> retrieving revision 1.192
>> diff -u -p -r1.192 ksh.1
>> --- bin/ksh/ksh.111 Aug 2017 23:10:55 -  1.192
>> +++ bin/ksh/ksh.118 Aug 2017 00:19:35 -
>> @@ -1614,16 +1614,15 @@ in
>> .Ev PS1 .
>> .It Li \e#
>> The current command number.
>> -This could be different to the current history number,
>> -if
>> +This may differ from the current history number if
> 
> what's there now is ok, and what you propose is ok. so the difference is
> really taste. in cases like that, i don;t think changing the text is
> worth it, unless you can see a clear improvement.
> 
> as to your point about to -> from, "different to" is in use. my
> student dictonary notes that "In British English, people sometimes say
> that one thing is different to another. Some people consider this use to
> be incorrect". but then the reverse is seemingly true of "different
> than".
> 
> i would just leave it.

Alrighty.

>> .Ev HISTFILE
>> contains a history list from a previous session.
>> .It Li \e$
>> -The default prompt i.e.\&
>> -.Sq # \&
>> +The default prompt character i.e.\&
>> +.Sq #\&
>> if the effective UID is 0,
>> otherwise
>> -.Sq $ \& .
>> +.Sq $\& .
>> Since the shell interprets
>> .Sq $
>> as a special character within double quotes,
>> 
> 
> i haven;t tested the space issue, but if it's correct i guess it needs
> fixing. however in that case the "\&" escaping is not needed.


Here's a tweaked diff:

Index: bin/ksh/ksh.1
===
RCS file: /cvs/src/bin/ksh/ksh.1,v
retrieving revision 1.192
diff -u -p -r1.192 ksh.1
--- bin/ksh/ksh.1   11 Aug 2017 23:10:55 -  1.192
+++ bin/ksh/ksh.1   18 Aug 2017 22:31:13 -
@@ -1619,11 +1619,11 @@ if
 .Ev HISTFILE
 contains a history list from a previous session.
 .It Li \e$
-The default prompt i.e.\&
-.Sq # \&
+The default prompt character i.e.\&
+.Sq #
 if the effective UID is 0,
 otherwise
-.Sq $ \& .
+.Sq $ .
 Since the shell interprets
 .Sq $
 as a special character within double quotes,

Re: ksh.1: two typos

[Scott Cheloha]

> On Aug 17, 2017, at 7:52 PM, Scott Cheloha <scottchel...@gmail.com> wrote:
> 
>> On Aug 17, 2017, at 7:47 PM, Theo Buehler <t...@theobuehler.org> wrote:
>> 
>> On Fri, Aug 18, 2017 at 02:37:51AM +0200, Theo Buehler wrote:
>>> On Thu, Aug 17, 2017 at 07:25:14PM -0500, Scott Cheloha wrote:
>>>> Spotted these when customizing my prompt.
>>>> 
>>>> I think "may differ from" is better than "could be different from,"
>>>> and you're free to (heh) differ, but in either case we get the
>>>> 
>>>>to -> from
>>> 
>>> I leave the first one one for jmc to decide, but I prefer the original
>>> wording about the prompt: PS1 *is* either '$ ' or '# ' by default.
>>> 
>>> See the lines following bin/ksh/main.c:312.
>>> 
>> 
>> Please ignore this. I looked at the wrong part of the man page.
>> 
>> The patch is ok tb if jmc doesn't object.
> 
> Just so everyone is clear, and for posterity, the second typo is
> that the escape sequence \$ does *not* produce a space character
> after the prompt character.  It only prints '$', or '#' if you
> are root.
> 
> Probably should have written that out explicitly.
> 
> -Scott

And by tech@ I meant to send that to bugs@.

Oh well.

ksh.1: two typos

[Scott Cheloha]

Spotted these when customizing my prompt.

I think "may differ from" is better than "could be different from,"
and you're free to (heh) differ, but in either case we get the

    to -> from

--
Scott Cheloha

Index: bin/ksh/ksh.1
===
RCS file: /cvs/src/bin/ksh/ksh.1,v
retrieving revision 1.192
diff -u -p -r1.192 ksh.1
--- bin/ksh/ksh.1   11 Aug 2017 23:10:55 -  1.192
+++ bin/ksh/ksh.1   18 Aug 2017 00:19:35 -
@@ -1614,16 +1614,15 @@ in
 .Ev PS1 .
 .It Li \e#
 The current command number.
-This could be different to the current history number,
-if
+This may differ from the current history number if
 .Ev HISTFILE
 contains a history list from a previous session.
 .It Li \e$
-The default prompt i.e.\&
-.Sq # \&
+The default prompt character i.e.\&
+.Sq #\&
 if the effective UID is 0,
 otherwise
-.Sq $ \& .
+.Sq $\& .
 Since the shell interprets
 .Sq $
 as a special character within double quotes,

fortune: Winston Churchill typo

[Scott Cheloha]

Due to something like the Echo Effect this particular typo has been
picked up from our collection by various online fortune/quote collections
and spread from there.

--
Scott Cheloha

Index: games/fortune/datfiles/fortunes
===
RCS file: /cvs/src/games/fortune/datfiles/fortunes,v
retrieving revision 1.51
diff -u -p -r1.51 fortunes
--- games/fortune/datfiles/fortunes 13 Jul 2017 02:45:56 -  1.51
+++ games/fortune/datfiles/fortunes 15 Aug 2017 16:02:53 -
@@ -8464,7 +8464,7 @@ Lunatic Asylum, n.:
 %
 Lysistrata had a good idea.
 %
-"MacDonald has the gift on compressing the largest amount of words into
+"MacDonald has the gift of compressing the largest amount of words into
 the smallest amount of thoughts."
-- Winston Churchill
 %

pledge.2: missed rename: request -> promises

[Scott Cheloha]

Hi,

The pledge(2) "request" parameter is now called "promises".

--
Scott Cheloha

Index: lib/libc/sys/pledge.2
===
RCS file: /cvs/src/lib/libc/sys/pledge.2,v
retrieving revision 1.43
diff -u -p -r1.43 pledge.2
--- lib/libc/sys/pledge.2   7 Jun 2017 20:53:59 -   1.43
+++ lib/libc/sys/pledge.2   11 Jun 2017 15:32:33 -
@@ -573,7 +573,7 @@ or one of its elements, or
 .Fa promises
 points outside the process's allocated address space.
 .It Bq Er EINVAL
-.Ar request
+.Ar promises
 is malformed or contains invalid keywords.
 .It Bq Er ENAMETOOLONG
 An element of

[patch] macppc/machdep.c: fix typo, no -> not

[Scott Cheloha]

The struggle is very real when you're getting kernel panics, but the
struggle needn't have typos.

--
Scott Cheloha

Index: sys/arch/macppc/macppc/machdep.c
===
RCS file: /cvs/src/sys/arch/macppc/macppc/machdep.c,v
retrieving revision 1.180
diff -u -p -r1.180 machdep.c
--- sys/arch/macppc/macppc/machdep.c30 Apr 2017 16:45:45 -  1.180
+++ sys/arch/macppc/macppc/machdep.c3 Jun 2017 14:20:04 -
@@ -712,7 +712,7 @@ dumpsys()
printf(str, error);
 
 #else
-   printf("dumpsys() - no yet supported\n");
+   printf("dumpsys() - not yet supported\n");

 #endif
delay(500); /* 5 seconds */

www: Dead link on macppc.html

[Scott Cheloha]

Hey,

The macppc platform page links to an explanation of the differences
between the OldWorld and NewWorld ROMs:

http://developer.apple.com/technotes/tn/tn1167.html

but that now redirects to the Apple developer API index.

The latest Wayback archive of the intended page is here:


https://web-beta.archive.org/web/2004104718/http://developer.apple.com/technotes/tn/tn1167.html

All archives after that date snagged the aforementioned redirect
instead.

--
Scott Cheloha

Seeming inconsistencies regarding ulimit between getrlimit(2), sh(1), POSIX.1-2008

[Scott Cheloha]

Hi,

getrlimit(2) says:

> Because this information is stored in the per-process information, this
> system call must be executed directly by the shell if it is to affect all
> future processes created by the shell; limit is thus a built-in command
> to csh(1) and ulimit is the sh(1) equivalent.

sh(1) hasn't mentioned ulimit since jmc@ rewrote it for revision
1.101.

POSIX.1-2008 says ulimit is an XSI option here:

http://pubs.opengroup.org/onlinepubs/9699919799/utilities/ulimit.html

sh(1) talks about how it is mostly POSIX.1-2008 compliant in its
STANDARDS section.  You can use ulimit from /bin/sh, with or without
POSIX mode.

ksh(1) defines ulimit in all its splendor, with its considerable
capabilities (relative to the POSIX.1-2008 spec), but does not
mention anything about POSIX, XSI, etc.

I think the simplest correction is to just change getrlimit(2)
to say "ksh" instead of "sh" (trivial patch below), so that the
documentation in the system itself is consistent... but elsewhere
in the manpages XSI extensions are marked and such, so I don't
know what else, if anything, should be changed.

Something just seems off, hence bugs@.

Thoughts?

--
Scott Cheloha

Index: getrlimit.2
===
RCS file: /cvs/src/lib/libc/sys/getrlimit.2,v
retrieving revision 1.27
diff -u -p -r1.27 getrlimit.2
--- getrlimit.2 7 Oct 2016 15:48:55 -   1.27
+++ getrlimit.2 15 Mar 2017 23:00:25 -
@@ -148,7 +148,7 @@ is thus a built-in command to
 and
 .Ic ulimit
 is the
-.Xr sh 1
+.Xr ksh 1
 equivalent.
 .Pp
 The system refuses to extend the data or stack space when the limits
@@ -206,7 +206,7 @@ and the caller is not the superuser.
 .El
 .Sh SEE ALSO
 .Xr csh 1 ,
-.Xr sh 1 ,
+.Xr ksh 1 ,
 .Xr quotactl 2 ,
 .Xr sigaction 2 ,
 .Xr sigaltstack 2 ,

wcscpy.3 mentions nonexistent EXAMPLES section in strcpy.3

[Scott Cheloha]

Hi,

The end of lib/libc/string/wcscpy.3 reads:

CAVEATS 
Using the functions wcscpy() and wcsncpy() is very error-prone 
with
respect to buffer overflows; see the EXAMPLES section in 
strcpy(3) for 
correct usage. Using wcslcpy(3) is a better choice in most 
cases.

But lib/libc/string/strcpy.3 has no EXAMPLES section.

Seen on OpenBSD 6.0 AMD64 (installed from the CD media), still present in CVS.

Cheers,
Scott Cheloha