Phidget Network Server Errors on Raspberry Pi 4

[AdamLee]

I'm running a Phidget Network Server in a Docket multi-container application and I'm seeing this on startup:

Code: Select all

2020-04-14T15:00:35 <ERROR> phidget22 : 
        ******************************  Logging Enabled  ******************************
        * Phidget22 - Version 1.6 - Built Mar 31 2020 18:37:30                        *
        *******************************************************************************
2020-04-14T15:00:35 <ERROR> phidget22[Zeroconf_publish()] : client is not initialized
2020-04-14T15:00:35 <ERROR> phidget22net[startServer()] : failed to publish '_phidget22server._tcp' on port 5661: 0x1c - Unexpected Error
2020-04-14T15:00:46 <ERROR> phidget22usb[PhidgetUSBGetString()] : libusb_get_string_descriptor_ascii() failed: LIBUSB_ERROR_TIMEOUT - Operation timed out.
2020-04-14T15:00:47 <ERROR> phidget22usb[PhidgetUSBGetString()] : libusb_get_string_descriptor_ascii() failed: LIBUSB_ERROR_TIMEOUT - Operation timed out.
2020-04-14T15:00:48 <ERROR> phidget22usb[PhidgetUSBGetString()] : libusb_get_string_descriptor_ascii() failed: LIBUSB_ERROR_TIMEOUT - Operation timed out.
2020-04-14T15:00:50 <ERROR> phidget22usb[PhidgetUSBGetString()] : libusb_get_string_descriptor_ascii() failed: LIBUSB_ERROR_TIMEOUT - Operation timed out.

I do have port 5661 opened up on the container and what's even crazier is I am successfully communicating with the network server from another container on the same device.

If anyone has any ideas on what could be causing these errors that would be exceptional. I've got a VINT hub, an 8/8/8 w/ USB hub and a bunch of other Phidgets all communicating without issue, until yesterday when all of a sudden I lose all Phidget connections randomly. So this is why I'm investigating.

ALSO - is there a place that has a little more documentation on the server? Mostly I'm looking for configuration options that I can change in phidget22networkserver.pc. I'd like to log to a persistent volume on the device where all my containers have access.

[AdamLee]

We also just started seeing these:

Code: Select all

2020-04-14T19:00:54 <ERROR> phidget22usb[PhidgetUSBSendPacket()] : libusb_control_msg() stalled too many times.
2020-04-14T19:00:54 <ERROR> phidget22[sendpacket()] : PhidgetUSBSendPacket() returned: 0x05 - IO Issue
2020-04-14T19:00:54 <ERROR> phidget22usb[PhidgetUSBSendPacket()] : libusb_control_msg() stalled too many times.
2020-04-14T19:00:54 <ERROR> phidget22[sendpacket()] : PhidgetUSBSendPacket() returned: 0x05 - IO Issue
2020-04-14T19:00:54 <ERR

[Patrick]

Have a look at README and networkserver.pc-dist in the Network server source download for documentation.

As for the USB errors - are you seeing any USB related errors in the system log at the same time? Could be power or EMI issues.

-Patrick

[AdamLee]

Thanks Patrick! I bumped the logging up to verbose and pointed the file to a persistent directory, so maybe we'll catch some more information. Any chance of you guys putting that source onto Github or something for easier access?

There are some interesting USB errors in the logs (running dmesg)... but it's hard to weed out the logs from around the time we were seeing these issues and just regular startup/shutdown. Since everything on the device is running in a container a lot of information is lost when the container restarts. I'll do a better job of offloading the logs the next time this happens.

I don't think power or EMI are issues since we've been running off this setup for a while now, but I won't count them out.

[AdamLee]

We had this issue again today, captured some better logs from the Phidget22 Network Server:

Code: Select all

2020-04-15T13:54:26 <ERROR> phidget22usb[PhidgetUSBSendPacket()] : libusb_control_msg() stalled too many times.
2020-04-15T13:54:26 <ERROR> phidget22[sendpacket()] : PhidgetUSBSendPacket() returned: 0x05 - IO Issue
2020-04-15T13:54:26  <Warn> phidget22[PhidgetUSBError()] : Detaching device because of USB error.
2020-04-15T13:54:26  <Info> phidget22net[removeChannelNetworkConnections()] : www,nodejs://127.0.0.1:39512 unlinked from RTD input Ch:0 -> TMP1200 -> HUB0000 Port:0 S/N:560574 Label:vhub
2020-04-15T13:54:26  <Info> phidget22[deviceDetach()] : TMP1200 (RTD Phidget) v106 -> HUB0000 Port:0 S/N:560574 Label:vhub
2020-04-15T13:54:26  <Info> phidget22net[removeChannelNetworkConnections()] : www,nodejs://127.0.0.1:39512 unlinked from PhidgetTemperatureSensor
2020-04-15T13:54:26  <Info> phidget22usb[PhidgetUSBReadPacket()] : libusb_interrupt_transfer() failed: LIBUSB_ERROR_IO - Input/Output Error. Maybe detaching?
2020-04-15T13:54:26  <Info> phidget22[deviceDetach()] : TMP1200 (RTD Phidget) v106 -> HUB0000 Port:1 S/N:560574 Label:vhub
2020-04-15T13:54:26  <Info> phidget22net[removeChannelNetworkConnections()] : www,nodejs://127.0.0.1:39512 unlinked from Digital Output Ch:0 -> OUT1100 -> HUB0000 Port:2 S/N:560574 Label:vhub
2020-04-15T13:54:26  <Info> phidget22net[removeChannelNetworkConnections()] : www,nodejs://127.0.0.1:39512 unlinked from Digital Output Ch:1 -> OUT1100 -> HUB0000 Port:2 S/N:560574 Label:vhub
2020-04-15T13:54:26  <Info> phidget22usb[PhidgetUSBReadPacket()] : libusb_interrupt_transfer() failed: LIBUSB_ERROR_IO - Input/Output Error. Maybe detaching?
2020-04-15T13:54:26  <Info> phidget22usb[PhidgetUSBReadPacket()] : libusb_interrupt_transfer() failed: LIBUSB_ERROR_IO - Input/Output Error. Maybe detaching?
2020-04-15T13:54:26  <Info> phidget22usb[PhidgetUSBReadPacket()] : libusb_interrupt_transfer() failed: LIBUSB_ERROR_IO - Input/Output Error. Maybe detaching?
2020-04-15T13:54:26  <Info> phidget22usb[PhidgetUSBReadPacket()] : libusb_interrupt_transfer() failed: LIBUSB_ERROR_IO - Input/Output Error. Maybe detaching?
last message repeated 16 times
2020-04-15T13:54:26  <Info> phidget22usb[PhidgetUSBReadPacket()] : Device was unplugged - detach.
2020-04-15T13:54:26  <Info> phidget22[PhidgetUSBReadThreadFunction()] : 1067 (PhidgetStepper Bipolar HC) v202 S/N:522891: ReadThread exiting normally (Phidget detach detected in PhidgetDevice_read)
2020-04-15T13:54:26  <Info> phidget22usb[PhidgetUSBReadPacket()] : Device was unplugged - detach.
2020-04-15T13:54:26  <Info> phidget22[PhidgetUSBReadThreadFunction()] : 1010/1018/1019 (PhidgetInterfaceKit 8/8/8) v904 S/N:594722: ReadThread exiting normally (Phidget detach detected in PhidgetDevice_read)

Immediately after I see the disconnects (again, dmesg):

Code: Select all

[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB2: usb_serial_generic_read_bulk_callback - urb stopped: -32
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB1: usb_serial_generic_read_bulk_callback - urb stopped: -32
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB0: usb_serial_generic_read_bulk_callback - urb stopped: -32
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB2: usb_serial_generic_read_bulk_callback - urb stopped: -32
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB1: usb_serial_generic_read_bulk_callback - urb stopped: -32
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB0: usb_serial_generic_write_bulk_callback - urb stopped: -32
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB0: usb_serial_generic_write_bulk_callback - urb stopped: -32
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB1: usb_serial_generic_write_bulk_callback - urb stopped: -32
[Wed Apr 15 13:54:27 2020] usb 1-1.2: USB disconnect, device number 7
[Wed Apr 15 13:54:27 2020] usb 1-1.2.1: USB disconnect, device number 8
[Wed Apr 15 13:54:27 2020] usb 1-1.2.2: USB disconnect, device number 9
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB0: error from flowcontrol urb
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB0: FTDI USB Serial Device converter now disconnected from ttyUSB0
[Wed Apr 15 13:54:27 2020] ftdi_sio 1-1.2.2:1.0: device disconnected
[Wed Apr 15 13:54:27 2020] usb 1-1.2.3: USB disconnect, device number 10
[Wed Apr 15 13:54:27 2020] usb 1-1.2.4: USB disconnect, device number 11
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB1: error from flowcontrol urb
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB1: FTDI USB Serial Device converter now disconnected from ttyUSB1
[Wed Apr 15 13:54:27 2020] ftdi_sio 1-1.2.4:1.0: device disconnected
[Wed Apr 15 13:54:27 2020] usb 1-1.2.5: USB disconnect, device number 12
[Wed Apr 15 13:54:27 2020] cdc_acm 1-1.2.5:1.0: failed to set dtr/rts
[Wed Apr 15 13:54:27 2020] usb 1-1.2.6: USB disconnect, device number 13
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB2: error from flowcontrol urb
[Wed Apr 15 13:54:27 2020] ftdi_sio ttyUSB2: FTDI USB Serial Device converter now disconnected from ttyUSB2
[Wed Apr 15 13:54:27 2020] ftdi_sio 1-1.2.6:1.0: device disconnected
[Wed Apr 15 13:54:27 2020] usb 1-1.2.7: USB disconnect, device number 14

I should note that everything we're connecting to has its own external power supply, other than the VINT hub of course.

[AdamLee]

One other addition - in order to resolve the issue today we had to power cycle the interface kit. Not sure if that gives any new leads but it's an additional data point.

I'm making some modifications now to cut down on the number of API calls/second to see if that alleviates the problem. More recently I think we had really ramped up our hit rate on the API.

[AdamLee]

Here's a new error message:

Code: Select all

2020-04-15T14:50:28  <Info> phidget22usb[PhidgetUSBReadPacket()] : libusb_interrupt_transfer() failed: LIBUSB_ERROR_IO - Input/Output Error. Maybe detaching?
2020-04-15T14:50:28 <ERROR> phidget22usb[PhidgetUSBGetString()] : libusb_get_string_descriptor_ascii() stalled too many times.
2020-04-15T14:50:28  <Warn> phidget22[scanVintDevices()] : Couldn't get VINT string from a Hub - maybe detaching.

[Patrick]

It looks like the 1019 builtin USB hub is disconnecting. I'm not sure why this would be happening - though I'm guessing either power issues, EMI, or hardware issues (bad USB cable, faulty 1019, faulty RPi, etc.). It would be good if you can cycle the hardware and try to track down what may be failing, perhaps starting with USB cables. You could also try offloading the USB devices plugged into the 1019 onto a different powered Hub, to rule out 1019 and/or power issues.

-patrick

[AdamLee]

We swapped some USBs.

We swapped the USB cable to the kit (it was actually on an extender /facepalm).

We swapped to a different interface kit since we have an inventory.

Still failed. What we're doing now is rolling back recent code changes to see if it's software related. Next step is to switch to a different powered hub. I'll keep this thread updated.

[AdamLee]

Interestingly enough we removed some programming to control three LEDs from the interface kit digital outs and this problem seems to have been alleviated somewhat. Seeing these now though:

Code: Select all

15.04.20 17:46:58 (-0500)  api  2020-04-15T22:46:58.402Z | error --> Phidget VoltageInput (diversionvalve) Error 4099: One or more data packets were lost
15.04.20 17:46:58 (-0500)  api  2020-04-15T22:46:58.411Z | error --> Phidget DigitalOutput (diversionvalve) Error 4099: One or more data packets were lost