KeyError -1

[lexe]

Dear,

First of all thanks for this library, it has been very useful.

In a (fast) cyclic program I occasionally get KeyError -1 exceptions when reading or writing data.

I get these messages when running the application in a console when the exceptions occur.
2017-09-27T21:44:38+0200 Warning: Port: 30001 already in use as 0

This is the only reference I found on the web describing the same error:
Beckhoff/ADS#20

Any idea how this can be solved?

Thanks in advance,

Alexander

[dabrowne]

That's an interesting one. Are you using multithreading or multiprocessing to make the pyads calls?

[lexe]

Hi,

Thanks for your quick reply. I simplified the code for testing and I'm still experiencing difficulties. The pyads calls are always made in the same thread.

This is how I set up my connection

    # init ads
    pyads.open_port()
    pyads.add_route(pyads.AmsAddr('192.168.10.30.1.1', pyads.PORT_SPS1), "192.168.10.30")
    self.con = pyads.Connection("192.168.10.30.1.1", 801)
    self.con.open()

    # start
    threading.Thread(target=self.run, name="plc_cyclic").start()

This is my cyclic code (run in the thread)

def read(self, plc_type, name):
    self.r += 1

    if plc_type == "x":
        return self.con.read_by_name(name, pyads.PLCTYPE_BOOL)
    elif plc_type == "b":
        return self.con.read_by_name(name, pyads.PLCTYPE_BYTE)
    elif plc_type == "si":
        return self.con.read_by_name(name, pyads.PLCTYPE_SINT)
    elif plc_type == "usi":
        return self.con.read_by_name(name, pyads.PLCTYPE_USINT)
    elif plc_type == "i":
        return self.con.read_by_name(name, pyads.PLCTYPE_INT)
    elif plc_type == "ui":
        return self.con.read_by_name(name, pyads.PLCTYPE_UINT)
    elif plc_type == "di":
        return self.con.read_by_name(name, pyads.PLCTYPE_DINT)
    elif plc_type == "udi":
        return self.con.read_by_name(name, pyads.PLCTYPE_UDINT)
    elif plc_type == "r":
        return self.con.read_by_name(name, pyads.PLCTYPE_REAL)

def run(self):
    sec_prev = -1
    self.cycle_time = 0
    while True:
        try:

            # LOGGING SENSOR STATES
            ts = datetime.datetime.now()
            if sec_prev != ts.second and ts.second == 0:
                print("cycle time: {0}s / reads: {1} / writes: {2}".format(self.cycle_time, self.r, self.w))
            if sec_prev != ts.second and ts.second == 0 and ts.minute % 15 == 0:
                self.read_sensors()
            sec_prev = ts.second

            # DETECT OBJECT STATE CHANGES
            for key in self.object_states:
                self.object_states[key]["value"] = self.read("udi", ".Global.State.dwObjStateChange_{0}".format(key))
            for oid in self.objects:
                idStart = oid // 32 * 32 + 1
                if self.object_states["{0:0>4}_{1:0>4}".format(idStart, idStart + 31)]["value"] & (1 << ((oid - 1) % 32)) > 0:                    
                    self.objects[oid].update_req = 1
            for key in self.object_states:
                if self.object_states[key]["value"] > 0:
                    self.write("udi", ".Global.State.dwObjStateChange_{0}".format(key), 0)

            # UPDATE OBJECTS
            for oid in self.objects:
                if self.objects[oid]:
                    self.objects[oid].update()

            self.cycle_time = (datetime.datetime.now() - ts).total_seconds()

        except:
            logging.Logging.log_ex(self)
            time.sleep(5)

This is the output of the above code

I've update to your latest version, now the exception is a little different comparing to the original KeyError -1 but I presume the inner exception is the same:

2017-09-28 09:28:34,753 [ERROR] dev.py:Controller(): ADSError exception at line 103: ADSError: Unknown Error (-1)

Any suggestions would be greatly appreciated.

Thanks in advance!

Alexander

[dabrowne]

I've done some research based on this issue you linked Beckhoff/ADS#20 and I believe you may be the victim of spurious failure of the c++ std::atomic::compare_exchange_weak method as part of the following block which is checking to avoid a race between requests. It's only meant to happen very occasionally, however given that you're making 16,000 calls so quickly I guess it's not surprising you're running into it.

if (!queue[port - Router::PORT_BASE].invokeId.compare_exchange_weak(isFree, id)) {
    LOG_WARN("Port: " << port << " already in use as " << isFree);
    return nullptr;
}

There's a good stackoverflow question on it here if you're interested, but I believe the solution may be to swap that out with compare_exchange_strong which isn't prone to the same failure mode. I can update this on my branch of the ADS lib https://github.com/dabrowne/ADS. When I've done so could you install adslib from that repo and see if you get the same issue?

[dabrowne]

@lexe Ok so I've made the update. Try the following and then run your code again.

git clone git@github.com:dabrowne/ADS.git
cd ADS
make

cp adslib.so /path/to/pyads/installation/adslib.so

[lexe]

Hi,

Thanks for you solution, I think it's safe to say all is working well now since i've not encountered new errors for at least 10 minutes (40000+ calls).

Thanks again for you quick solution to this.

Regards,

Alexander

[dabrowne]

Great to hear it seems to be fixed. Thanks for the thorough bug report. Keep us updated if anything changes. I'll try and get this change propagated up to the Beckhoff/ADS master.

Stefan will need to update the pyads submodule link to my repo for the change to be included in the next pyads release. @MrLeeH