[2.2.5.223 C7] NPE When adding lock code via Lock Code Manager

[rob9]

@bcopeland @gopher.ny Not sure who might want to look at this:

I tried to add a lock code to a new Schlage S2 lock and remove it from an Schlage S0 old lock (both locks are powered on and within a few feet of the hub).

I got this:

The NPEs occurred ADDing the code to the NEW lock. In the Event Log, I see (from bottom to top):

LockCodes (the list)
CodeChange (added)
CodeChange (changed)
lockCodes (the list)
lockCodes(the list)
codeChanged (changed)

The initial "added" corresponds to the first NPE

The next two "changed" ones correspond to the 2nd and 3rd NPE.

It appears the lock code got sent and updated (and the Lock Code Manager seems to know about it??).

Note1: There were ZERO lock codes already on the new lock. I intentionally performed a "delete all user codes" from the keypad to start off with a clean slate.

Adding the second code did not throw the NPE--but, it ALSO did not actually run the jobs. Ugh. It seems, possibly, that the NPE blew up some internal process, The jobs were stuck "pending", neither lock had the second lock code processed and the jobs were simply not seeming to run.

I rebooted the hub. The jobs were still pending. However, when I tried to add a 3rd code, it appeared the jobs kicked off. And, they DID generate NPEs again.

Note2: Another NPE issue in the Lock Code Manager:

This came up when I was just looking at the lock codes to validate what was there (I clicked on a lock code, then clicked "Done" without doing anything and got an error on the web page and the NPE in the log; I believe THIS error has existed for many versions as it seem to ring a bell).

[mike.maxwell]

Let's see of you can make these changes from the lock driver before trying them with lcm.

[rob9]

@mike.maxwell

make these changes from the lock driver

Well, I'd already used the lock code manager to add all my codes. For whatever reason, after I'd rebooted, the NPEs didn't cause the jobs to get stuck in the queue.

Perhaps there's another 2.2.5.x bug that caused that?

In any case, I added an additional code manually and it worked with no NPEs.

My manual deletion request, however, is being less cooperative. I entered it in and, thus far, all I see is the "requestedChange" state variable showing the "status=D" for the code. Nothing at all in the regular log.

I then did a "Get Codes" and the "requestedChange" field emptied out. However, the "current States" has NOT dropped that code yet and the code still does work.

It's really hard to tell what's happening, as the driver is not logging anything.

I rebooted for S&Gs.

This time, when I tried to delete the code, it did drop from the list (almost immediately). HOWEVER, nothing is logging still. I "re-saved" my preferences and, lo and behold, it resumed logging.

A couple other notes:

1. The "codeFetchComplete" was = 0 during my lcm issues. I manually did a "code fetch"

2. Logging seems very spotty for this device. Despite having "Debug Logging" and "descriptionText logging" both on for the device, I'm not really seeing much in my log.

[mike.maxwell]

The lock isn't responding to the commands, so there's a mesh issue of some sort.

[rob9]

It responded as best I could tell, regardless of the debug info.

I managed to get all the codes set and it's responding to commands about as well as any other lock.

The lock was about 3 feet or less from the hub in open air.

There's certainly no reason there should be "mesh issues" with a direct route from the hub to a lock 3 feet away--nothing else was between it and the rest of my devices were essentially idled.

I can't think of how there could be a "mesh issue"--at least not one on my end.

[rob9]

To elaborate a bit on what I was seeing:

Something hosed up the both logging settings. Despite them being enabled on the screen, they were clearly not in effect.

After rebooting AND re-saving the preferences, logging resumed as normal/expected.

The best I could tell from what was making it to the lock (and by watching the Z-Wave logging fly by), things WERE getting to the lock as expected.

From what I'm seeing there are likely multiple issues:

1. Some bug in the LCM is throwing an NPE during an "add" in some conditions (possibly, when the State variable codeFetchComplete=0

2. A bug in the LCM that sometimes happens when you look at a user entry without doing anything and just click "Done" (this appears to be a "Cannot get property 'user' on null object on line 460 (codeManagement)".

3. Possibly, some issue with tracking/setting logging in the "Schlage BE468/BE469 Lock" driver.

4. Some general issues with Z-Wave traffic that particularly impacts locks, possibly related to S0/S2-Access encrypted devices. I suspect the ACKs are not being managed properly because I notice this most acutely when I issue a lock or unlock command--it seems that the device is not receptive to further commands until some period of time passes (which is behavior that seems to occur when a device is stuck waiting on an ACK that never come).

About #4, I have issues with ALL of my locks where it can take several attempts to get the locks to lock or unlock from the hub. These issues are significantly worse with the legacy ZW/S0 locks, but even the ZWP/S2 one has issues (now, I have 2 ZWP/S2 ones, as this new lock replaced one of my S0 ones, specifically due to issues I was having with events from the S0 locks).

When @bcopeland made his big z-wave "re-write", things did get a lot better. Even with the S0 locks. What I notice then, however, was that the FIRST lock/unlock I'd issue would almost always work VERY quickly. However, if I issued the opposite command right away, the device wouldn't respond. I needed to wait a while or keep trying over & over before it eventually worked.

The more I think about it, the more I suspect there is something going on with the ACKs. This is very similar behavior to what I saw recently with my Ring Extender, where it would send an event when you unplugged it-but if you plugged it in before waiting a while, it never sent the "mains power" event. Again, that was an S2 device.

This thread discusses similar issues with my Ring Contact Sensors and the Ring Extender (with some other people's comments and issues in the mix):

@rob9

@bcopeland - super strange--but I believe this to be a case of missing ACK packets for S2-encrypted devices.

I started out noticing that it seems there are issues if you plug/unplug the extender too rapidly.

There seems to be a second "disconnected" message sent about 20 or so secs AFTER the first one (the first one fires right after it is unplugged). Same on the re-connect.

This shows a SINGLE unplug--wait--re-plug action for my extender.

[rob9]

Here's the z-wave log, as that shows the issue a bit more (the regular log only shows the commands that seem to work):

All of those ~119 ms events are ones that failed. Notice that they don't show the speed and rssi either.

I tried some other experiments:

It seems the seqNo values are generally in pairs. I issue the command--and two lines pop up with the same seqNo, with a slight delay between them.

The first line (bottom one in the last pic) was interesting--as it came back with a 1ms time but the second line took 118ms. It and the others failed to unlock the "Office Door Lock" until the seqNo=209 try. It took 118ms on the first line--but the second one came back in 1ms and it had all the speed/rssi data.

Not sure if that helps pinpoint what's going on or not--but this, combined with the S2 Ring device issue kinda makes me wonder.

FYI: I also have a GE/Jasco ZWP/S2 Authenticated dimmer switch. In general, it seems to work pretty well. However, I did encounter something odd testing it just now. it's behavior differs in that there is only one zwave log line per seqNo (it seems to generate two log lines per action, but the numbers are unique). And, while it seemed to respond immediately and properly to multiple on/off commands in a row, I waited a bit to issue some more--and that time, it ignored several on/off commands. I waited a bit then did a "refresh" and, suddenly, it seemed to start working again.

HOWEVER, the seqNo behavior was changed. Before, the seqNos seemed to increment between the two lines (if the first was 124, the next was 124). However, after the device hung up, there was a disparity (e.g., the first was 132, the second was 126)--so, perhaps, something lost count (and, it did result in those seqNos being "reused" subsequently). Here are those relevant logs: