Created attachment 1363341 [details]
Output of upsdrvctl -D start with ups1 configured for SNMPv1, others for SNMPv3.

Description of problem:
On startup of snmp-ups talking with fairly old (circa 2010) APCC Smart-UPS 5000 AP9617 or AP9619 cards the following errors are reported:

When configured for SNMPv3:
Dec  5 08:25:07 nomaddev upsdrvctl: Detected Smart-UPS 5000 on host [redacted] (mib: apcc 1.2)
Dec  5 08:25:12 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.3.1.1.1
Dec  5 08:25:13 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.3.1.1.2
Dec  5 08:25:13 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.3.1.1.3
Dec  5 08:25:13 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.4.1.1.1
Dec  5 08:25:14 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.4.1.1.2
Dec  5 08:25:14 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.4.1.1.3
Dec  5 08:25:14 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.5.1.1.1
Dec  5 08:25:14 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.5.1.1.2
Dec  5 08:25:15 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.5.1.1.3
Dec  5 08:25:15 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.6.1.1.1
Dec  5 08:25:15 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.6.1.1.2
Dec  5 08:25:16 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.6.1.1.3
Dec  5 08:25:16 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.7.1.1.1
Dec  5 08:25:16 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.7.1.1.2
Dec  5 08:25:17 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.7.1.1.3
Dec  5 08:25:17 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.8.1.1.1
Dec  5 08:25:17 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.8.1.1.2
Dec  5 08:25:17 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.3.1.8.1.1.3
Dec  5 08:25:18 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.2.2.1.4.1
Dec  5 08:25:24 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.2.3.5.0
Dec  5 08:25:24 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.2.3.6.0
Dec  5 08:25:27 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.2.1.4.1
Dec  5 08:25:28 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.3.1.1.1
Dec  5 08:25:28 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.3.1.1.2
Dec  5 08:25:28 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.3.1.1.3
Dec  5 08:25:29 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.4.1.1.1
Dec  5 08:25:29 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.4.1.1.2
Dec  5 08:25:29 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.4.1.1.3
Dec  5 08:25:29 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.5.1.1.1
Dec  5 08:25:30 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.5.1.1.2
Dec  5 08:25:30 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.5.1.1.3
Dec  5 08:25:30 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.6.1.1.1
Dec  5 08:25:31 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.6.1.1.2
Dec  5 08:25:31 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.6.1.1.3
Dec  5 08:25:31 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.7.1.1.1
Dec  5 08:25:32 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.7.1.1.2
Dec  5 08:25:32 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.7.1.1.3
Dec  5 08:25:32 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.8.1.1.1
Dec  5 08:25:32 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.8.1.1.2
Dec  5 08:25:33 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.8.1.1.3
Dec  5 08:25:33 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.9.1.1.1
Dec  5 08:25:33 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.9.1.1.2
Dec  5 08:25:34 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.9.1.1.3
Dec  5 08:25:34 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.10.1.1.1
Dec  5 08:25:34 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.10.1.1.2
Dec  5 08:25:34 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.10.1.1.3
Dec  5 08:25:35 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.11.1.1.1
Dec  5 08:25:35 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.11.1.1.2
Dec  5 08:25:35 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.11.1.1.3
Dec  5 08:25:36 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.12.1.1.1
Dec  5 08:25:36 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.12.1.1.2
Dec  5 08:25:36 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.1.9.3.3.1.12.1.1.3
Dec  5 08:25:37 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.2.1.1.0
Dec  5 08:25:38 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.2.1.2.0
Dec  5 08:25:39 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.10.2.3.2.1.4.1
Dec  5 08:25:39 nomaddev upsdrvctl: [ups3-1] unhandled ASN 0x81 received from .1.3.6.1.4.1.318.1.1.10.2.3.2.1.6.1

When configured for SNMPv1:
Dec  5 08:24:58 nomaddev upsdrvctl: Detected Smart-UPS 5000 on host [redacted] (mib: apcc 1.2)
Dec  5 08:24:59 nomaddev upsdrvctl: [ups1-1] Warning: excessive poll failures, limiting error reporting
Dec  5 08:25:00 nomaddev upsdrvctl: [ups1-1] Warning: excessive poll failures, limiting error reporting


Version-Release number of selected component (if applicable):
nut-2.7.2-3.el7.x86_64
CentOS 7 - Linux [redacted] 3.10.0-693.5.2.el7.x86_64 #1 SMP Fri Oct 20 20:32:50 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

UPSs:
AP9617 A10, sumx v3.7.2, aos v3.7.3
AP9619 A10, sumx v3.7.2, aos v3.7.3

SNMP MIB (reported by upsc):
driver.parameter.mibs: apcc
driver.version.data: apcc MIB 1.2


How reproducible:
It happens for three different UPSs. Two have AP9617 cards and one has an AP9619 card.


Steps to Reproduce:
1. install nut-2.7.2-3 configured for snmp-ups using SNMPv3 talking with APC UPSs
2. systemctl start nut-driver
3. check /var/log/messages


Actual results:
When configured for SNMPv3, nut startup is very slow (generally about 5 minutes but sometimes long enough for it to exceed TimeoutSec and completely fail). In the process it tries upwards of 7-8 times (though usually just 2-3) to start each snmp-ups process. 

Additionally, at random times upsmon logs reports of COMBAD followed by COMOK 5 seconds later (e.g. 22 times overnight last night). These messages only happen when snmp-ups is configured to use SNMPv3. A quick look seems to imply it only complains about the UPS with the AP6919 card. This may or may not be related SNMPv3 MIB issues.

In order to get nut-driver.service & nut-server.service to launch successfully I had to add the following to /etc/systemd/system/nut-driver.service.d/nut-driver.conf 
[Unit]
StopWhenUnneeded=no

[Service]
TimeoutSec=600

(The StopWhenUnneeded=no was necessary as systemd was killing the snmp-ups processes when they launched successfully, logging a message about them not being needed.)

I also had to add the following to ups.conf:
maxretry = 10
retrydelay = 15

These changes result in a fragile, flaky, slow to start service and are highly undesirable. If I don't make these changes then I have to use SNMPv1 to talk with two of the three UPSs (any two, it doesn't matter which ones I choose). Leaving all settings at default and selecting SNMPv3 for two or more UPSs result in NUT failing to start. 

These are the only changes from default I've made, other than configuring the necessary SNMP information for accessing the UPS.


Expected results:
Quick startup with only one try needed to launch snmp-ups, no COMBAD/COMOK combinations after startup.


Additional info:
Startup with SNMPv1 seems to happen quickly but also seems to have problems based on the poll failures.