Slow memory leak in ibootbar agents when hardware is offline

[BrianJKoopman]

On satp2 there were a bunch of ibootbar agents running for hardware that is currently offline. They, over the course of 30+ days grew to ~7% memory usage each. There were eight running, so this was quite a bit of the memory of the machine.

Seeing as we don't see agents on other platforms running away, I suspect it's something to do with the hardware being offline, like we've seen in other agents (see #851 for instance).

My other suspicion is there's something to do with our SNMP implementation, since we had a similar issue with the UPS agents, which we implemented #592 as a workaround.

Either way this needs investigation at some point.

socs version: v0.5.3-3-g94412e0-dev

[mjrand]

Is this a logging multiple times a second problem as well as the HWP gripper agent? When acq is running but loses contact with the SNMP its not handled and will probably loop infinitely and log multiple times a second.

    while self.is_streaming:
            yield dsleep(1)
            if not self.connected:
                self.log.error('No SNMP response. Check your connection!')
                self.log.info('Trying to reconnect.')

            read_time = time.time()

            # Check if sample period has passed before getting status
            if (read_time - self.lastGet) < self.sample_period:
                continue

            get_list = []
            name_list = []
            names = []

            # Create the lists of OIDs to send get commands
            for i in range(8):
                get_list.append((self.ibootbar_type + '-MIB', 'outletStatus', i))
                name_list.append((self.ibootbar_type + '-MIB', 'outletName', i))

            # Issue SNMP GET commands
            get_result = yield self.snmp.get(get_list, self.version)
            if get_result is None:
                self.connected = False
                session.data['ibootbar_connection'] = {'last_attempt': time.time(),
                                                       'connected': False}
                continue

In this function if a get from the SNMP ever fails for whatever reason self.connected gets set to False and the loop continues.
Then the case if not self.connected is triggered which logs twice.
The log says its trying to reconnect but it doesn't actually do anything.

Then the loop continues again, assumedly triggering the get failure infinitely in the same pattern.

[mjrand]

The UPS agent does the same thing:

    while self.is_streaming:
            if ((self.restart != 0) and (time.time() > timeout)):
                break
            yield dsleep(1)
            if not self.connected:
                self.log.error('No SNMP response. Check your connection.')
                self.log.info('Trying to reconnect.')

            read_time = time.time()

            # Check if 60 seconds has passed before getting status
            if (read_time - self.lastGet) < 60:
                continue

            main_get_list = []
            get_list = []

            # Create the list of OIDs to send get commands
            oids = ['upsIdentManufacturer',
                    'upsIdentModel',
                    'upsBatteryStatus',
                    'upsSecondsOnBattery',
                    'upsEstimatedMinutesRemaining',
                    'upsEstimatedChargeRemaining',
                    'upsBatteryVoltage',
                    'upsBatteryCurrent',
                    'upsBatteryTemperature',
                    'upsOutputSource']

            for oid in oids:
                main_get_list.append(('UPS-MIB', oid, 0))
                get_list.append(('UPS-MIB', oid, 0))

            ups_get_result = yield self.snmp.get(get_list, self.version)
            if ups_get_result is None:
                self.connected = False
                continue

All of the agents that have these memory problems with the hardware offline seem to have loops that cause infinite logging.

[mjrand]

@BrianJKoopman can we try PR'ing in a break for the acq process if self.connected becomes False before the site computing move to see if that helps the memory leak? it would be pretty similar to the break David added every hour (maybe we should remove that, or we can test on the ibootbar agent if there is a bootbar involved in the computing move? (The acq/agent should probably die if the UPS becomes disconnected anyways so an alert can fire and alert people anyways... or actually try and reconnect)

[mjrand]

One of the iboot agents did indeed create tens of thousands of logs during the compute move (which pales in comparison to the literally millions generated by the pmx agents)

[BrianJKoopman]

Hey @mjrand, sorry for the slow response here, and thanks for looking into this. I don't think the logging itself would be increasing memory like this, it just goes to stdout. On the docker end this could increase disk usage if log rotation isn't setup.

The log says its trying to reconnect but it doesn't actually do anything.

The SNMPTwister.get() should automatically reconnect on the next call when hardware is back online, so there isn't anything else to do, which is why if get_result is None we continue.

Since this leaks without hardware, it'd be easy to test whatever fix you're suggesting by running a local instance of the agent. Removing that 1 second sleep at the start of the loop will also likely increase the rate of the leak, which would be helpful for testing.