Run-time error in Adapter.sendPacket()

[jsquyres]

I was running my first trivial green been application this morning (source included below) on a Raspberry Pi (Raspbian GNU Linux 7 / Linux redbox-raspberrypi 3.12.28+ #709 PREEMPT Mon Sep 8 15:28:00 BST 2014 armv6l GNU/Linux), and it appeared to be working fine -- it immediately reported a bunch of values from my Hawk dryer:

$ sudo /home/pi/nodejs-local/bin/node status.js  
machine status changed: 0
machine sub-cycle changed: 0
cycle count changed: 611
time remaining changed: 0
selected cycle changed: 8
operating mode changed: 0

I left it running and walked away from my computer. About 1.5 hours later, I returned to see the following stack trace on the screen:

events.js:74
        throw TypeError('Uncaught, unspecified "error" event.');
              ^
TypeError: Uncaught, unspecified "error" event.
    at TypeError (<anonymous>)
    at Adapter.emit (events.js:74:15)
    at sendPacket (/home/pi/node_modules/green-bean/node_modules/gea-adapter-usb/index.js:55:18)
    at Adapter.send (/home/pi/node_modules/green-bean/node_modules/gea-adapter-usb/index.js:150:9)
    at Adapter.bus.send (/home/pi/node_modules/green-bean/node_modules/gea-sdk/src/command.js:46:9)
    at null.<anonymous> (/home/pi/node_modules/green-bean/node_modules/gea-sdk/src/appliance.js:464:13)
    at wrapper [as _onTimeout] (timers.js:261:14)
    at Timer.listOnTimeout [as ontimeout] (timers.js:112:15)

I'm out of time to dig deeper right now, but I'm curious to know if you have seen such errors before. Are there typical causes / bozo errors that cause this kind of thing?

More detail

You'll have to forgive me; I'm entirely new to Javascript (I'm a C dev in my day job); what's the typical way to get more information from a sub-module that emits an amorphous error?

I notice that the error occurs in Adaper.send at this block (https://github.com/GEMakers/gea-adapter-usb/blob/master/index.js#L51):

try {
    hid.write(writer.toArray());
}
catch (error) {
     self.emit("error", error);
}

It's unfortunate that it's not more descriptive on what the error is, but clearly it erred in trying to write to the GB device.

It looks like node-hid is a dependent module; I see C++ source code for HID::write() (i.e., Javascript hid.write()) under ~/node_modules/green-bean/node_modules/gea-adapter-usb/node_modules/node-hid. The only error I see occurring in there is at https://github.com/node-hid/node-hid/blob/master/src/HID.cc#L172, where hid_write() fails. Looking into the source for node-hid, it looks like on Linux, hid_write() is essentially a wrapper around write(2) (see https://github.com/signal11/hidapi/blob/master/linux/hid.c#L666).

On my RPi, I simply used "npm install green-bean", which installed all the GEA sub-modules for me, to include node-hid (which seems to have sub-included hidapi). I see the source under ~/node_modules/.../node-hid, but it doesn't look like it was compiled there, so it's not just a trivial "add errno to the JSException string" and recompile.

I can figure out to compile hidapi for myself later (e.g., to see the errno value), but I'm out of time for now. Hence, I'm just curious as to whether you've seen this kind of error before, and if it's due to a bozo user error. :-)

The trivial application is below.

var greenBean = require("green-bean");

greenBean.connect("laundry", function(laundry) {
    laundry.machineStatus.subscribe(function (value) {
        console.log("machine status changed:", value);
    });

    laundry.machineSubCycle.subscribe(function (value) {
        console.log("machine sub-cycle changed:", value);
    });

    laundry.endOfCycle.subscribe(function (value) {
        console.log("end of cycle changed:", value);
    });

    laundry.cycleCount.subscribe(function (value) {
        console.log("cycle count changed:", value);
    });

    laundry.dryerServiceErrorCodes.subscribe(function (value) {
        console.log("dryer service error codes changed:", value);
    });

    laundry.maximumWaterTemperature.subscribe(function (value) {
        console.log("maximum water temperature changed:", value);
    });

    laundry.timeRemainingInSeconds.subscribe(function (value) {
        console.log("time remaining changed:", value);
    });

    laundry.tankStatus.subscribe(function (value) {
        console.log("tank status changed:", value);
    });

    laundry.tankSelected.subscribe(function (value) {
        console.log("selected tank changed:", value);
    });

    laundry.cycleSelected.subscribe(function (value) {
        console.log("selected cycle changed:", value);
    });

    laundry.operatingMode.subscribe(function (value) {
        console.log("operating mode changed:", value);
    });

    laundry.delayTimeRemainingInMinutes.subscribe(function (value) {
        console.log("delay time remaining changed:", value);
    });
});

[jsquyres]

Another symptom that might be related...

I ran a load of towels in the Hawk and left the simple program listed above running.

It initially reported a bunch of information, but then stopped reporting anything -- it didn't report the end of cycle, for example, nor did it report decreasing time left as the cycle progressed. Here's the output from my simple program:

machine status changed: 0
machine sub-cycle changed: 0
time remaining changed: 0
selected cycle changed: 8
operating mode changed: 0
end of cycle changed: 0

# I turned the Hawk on here
machine status changed: 1
time remaining changed: 1080

# I changed it to the towels cycle
time remaining changed: 1200
selected cycle changed: 6

# I cycled through the heat (from "high" back to "high", actually)
time remaining changed: 1260
time remaining changed: 1200

# I started the cycle
machine status changed: 2
machine sub-cycle changed: 128
cycle count changed: 612

I think the cycle count changed when it was done, but I'm not sure -- I wasn't watching it to see when it happened (note to self: output timestamps with the data...).

Is this expected behavior?

[MylesCaley]

Jeff, thanks for the great details and working with the Green Bean. We too are mostly C developers and releasing Green Bean has been a pet project among several of us for awhile (and very excited it was recently opened to the public).

We have indeed seen this issue before and unfortunately don't have a fix for it. Something is blowing a gasket down at the HID layer as you indicated. Getting the errno from write() would be the right next step. I'd be very appreciative if you wanted to dive in and contribute a pull request on this (if we need to put a workaround in due to HID layer). Ill chat with the other devs this afternoon as well.

[jsquyres]

Cool, I'll do so (get the errno, etc.) -- possibly this evening. Must stop playing with this now and go work at my real day job... :-)

[jsquyres]

One last thing... ctrl-C'ed the frozen app and re-ran it again, and I notice several values changed:

machine status changed: 4
machine sub-cycle changed: 0
end of cycle changed: 1
time remaining changed: 0
selected cycle changed: 6
operating mode changed: 0

Seems to imply that it somehow stopped getting information from the machine partway through the towel dry cycle. Specifically: it got new data when I ran it again, which implies it might not be the USD driver for the GB itself, but might just be the userspace layer (e.g., something in node-hid or hidapi?).

Ok, I really must go do what they pay me to do now...

[jsquyres]

I'll try some more laundry tomorrow with my modified hidapi, and see if this fixes things (I'm not sure offhand if Github notifies you when I refer to this issue from a different issue -- see signal11/hidapi#190).

(BTW, I was incorrect above when I said that hid_write() was basically a wrapper around write(2) -- with more tracing, I discovered that my hidapi was using the libusb implementation of hid_write(), which uses a different mechanism)

The lack of a hidapi timeout definitely fixes the initial stack trace that I reported; I'm not 100% sure it will fix the "stopped getting information" issue that I described in https://github.com/GEMakers/gea-sdk/issues/2#issuecomment-57163399 -- that might end up being a separate issue.

[jsquyres]

I've done a load of laundry and dried it, and the timeout problem seems to have disappeared after removing the timeout in hid_write().

I am still experiencing the "stop receiving data" issue, however. That seems like a different problem; I'll open a new issue for it and put the data I've collected so far on it.

@MylesCaley I'll let you decide whether you want to keep this issue open (it's not technically a problem with the GEA SDK, but it might be useful to track if/when they fix the problem in hidapi upstream).

[MylesCaley]

@jsquyres yes, I'll keep this open for a few more days, hopefully the signall11 repo will get that fixed soon. Good catch and thanks for diving into that. We can at least give people a workaround until this is resolved. wrt to the stop receiving data issue... yes, open up a ticket and I have some initial questions for you....

[ryanplusplus]

@MylesCaley Is it worth forking hid-api in the short term to fix the issue? I think it would be as simple as changing the package.json to point to our fork.

On Tue, Sep 30, 2014 at 9:13 AM, Myles Caley notifications@github.com wrote:

@jsquyres https://github.com/jsquyres yes, I'll keep this open for a few more days, hopefully the signall11 repo will get that fixed soon. Good catch and thanks for diving into that. We can at least give people a workaround until this is resolved. wrt to the stop receiving data issue... yes, open up a ticket and I have some initial questions for you....

— Reply to this email directly or view it on GitHub https://github.com/GEMakers/gea-sdk/issues/2#issuecomment-57311105.

[ryanplusplus]

@jsquyres I just submitted a fix for the subscription issue you are seeing. Check out https://github.com/GEMakers/gea-sdk/pull/3.

On Tue, Sep 30, 2014 at 9:24 AM, Ryan Hartlage ryanplusplus@gmail.com wrote:

@MylesCaley Is it worth forking hid-api in the short term to fix the issue? I think it would be as simple as changing the package.json to point to our fork.

On Tue, Sep 30, 2014 at 9:13 AM, Myles Caley notifications@github.com wrote:

@jsquyres https://github.com/jsquyres yes, I'll keep this open for a few more days, hopefully the signall11 repo will get that fixed soon. Good catch and thanks for diving into that. We can at least give people a workaround until this is resolved. wrt to the stop receiving data issue... yes, open up a ticket and I have some initial questions for you....

— Reply to this email directly or view it on GitHub https://github.com/GEMakers/gea-sdk/issues/2#issuecomment-57311105.

[ryanplusplus]

@jsquyres the subscription fix has been merged. Run npm update and you should be able to keep a subscription open to your dryer.

[EvilDrW]

@ryanplusplus just wanted to chime in and say that the subscription fix cleared up problems I was experiencing with https://github.com/FirstBuild/Chillhub although, running npm update didn't actually do anything... i had to manually pull in the updated erd.js

[jsquyres]

FWIW, I got the subscription fix via "npm update", but it erased my hidapi fix because it pulled down a new copy of hidapi. Easy to fix and not entirely unexpected, but figured I'd mention it here for completeness...

On Tue, Sep 30, 2014 at 11:56 AM, EvilDrW notifications@github.com wrote:

@ryanplusplus https://github.com/ryanplusplus just wanted to chime in and say that the subscription fix cleared up problems I was experiencing with https://github.com/FirstBuild/Chillhub although, running npm update didn't actually do anything... i had to manually pull in the updated erd.js

— Reply to this email directly or view it on GitHub https://github.com/GEMakers/gea-sdk/issues/2#issuecomment-57336521.

{+} Jeff Squyres

[rudybrian]

Thanks for the subscription fix @ryanplusplus, it does indeed seem to have addressed the issue of subscription updates stopping after a short while with my GFDR485GF0MC dryer.