search

AllskyTeam / allsky

A Raspberry Pi operated Wireless Allsky Camera
MIT License
1.16k stars 180 forks source link

Error ZWO ASI385MC #3831

Open WirthmU opened 3 weeks ago

WirthmU commented 3 weeks ago

I have installed a fresh version of Allksy on an RPi 4 Model B Rev 1.1 (RPi 4 Model B Rev 1.1) running bullseye. Installation went smooth and ZWO ASI camera was detected up and running. Now after a certain time allksy stops working with red message on the screen (Allsky is not running).

This is what the logfile says:

Aug 21 20:09:25 allsky allsky[877]: STARTING EXPOSURE at: 2024-08-21 20:09:25   @ 4.48 ms
Aug 21 20:09:25 allsky allsky[877]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=32, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 21 20:09:25 allsky allsky[877]: *** /home/pi/allsky/bin/capture_ZWO: ERROR: flushBufferedImages() setControl() returned ASI_ERROR_GENERAL_ERROR (16)
Aug 21 20:09:25 allsky allsky[877]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=4482, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 21 20:09:30 allsky allsky[877]:   > /home/pi/allsky/bin/capture_ZWO: ERROR: Failed getting image: ASI_ERROR_TIMEOUT (with 0.8 exposure = YES) (11)
Aug 21 20:09:32 allsky allsky[877]: *** /home/pi/allsky/bin/capture_ZWO: ERROR: Maximum number of consecutive errors of 5 reached; capture program exited.
Aug 21 20:09:35 allsky allsky[877]:      ***** Stopping AllSky *****
Aug 21 20:09:36 allsky allsky[747]: Stopping Allsky: Allsky Stopped!<br>Non-recoverable ERROR found<br>See /var/log/allsky.log.
Aug 21 20:09:36 allsky allsky[747]:      ***** AllSky Stopped *****

After a re-boot it works for sometime and then again:

Aug 22 09:35:29 allsky allsky[3132]:    Allsky version: v2023.05.01_04
Aug 22 09:35:29 allsky allsky[3132]:    ZWO SDK version 1, 32, 0, 0
Aug 22 09:35:29 allsky allsky[3132]: ==========
Aug 22 09:35:29 allsky allsky[3132]: === Starting daytime capture ===
Aug 22 09:35:29 allsky allsky[3132]: ==========
Aug 22 09:35:29 allsky allsky[3132]: STARTING EXPOSURE at: 2024-08-22 09:35:29   @ 100.00 ms (0.10 sec)
Aug 22 09:36:04 allsky allsky[3132]: STARTING EXPOSURE at: 2024-08-22 09:36:04   @ 550 us (0.550 ms)
Aug 22 09:36:04 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=32, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:04 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: ERROR: flushBufferedImages() setControl() returned ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:04 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=550, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:09 allsky allsky[3132]:   > /home/pi/allsky/bin/capture_ZWO: ERROR: Failed getting image: ASI_ERROR_TIMEOUT (with 0.8 exposure = YES) (11)
Aug 22 09:36:11 allsky allsky[3132]: STARTING EXPOSURE at: 2024-08-22 09:36:11   @ 550 us (0.550 ms)
Aug 22 09:36:11 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=32, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:11 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: ERROR: flushBufferedImages() setControl() returned ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:11 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=550, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:16 allsky allsky[3132]:   > /home/pi/allsky/bin/capture_ZWO: ERROR: Failed getting image: ASI_ERROR_TIMEOUT (with 0.8 exposure = YES) (11)
Aug 22 09:36:19 allsky allsky[3132]: STARTING EXPOSURE at: 2024-08-22 09:36:19   @ 550 us (0.550 ms)
Aug 22 09:36:19 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=32, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:19 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: ERROR: flushBufferedImages() setControl() returned ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:19 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=550, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:24 allsky allsky[3132]:   > /home/pi/allsky/bin/capture_ZWO: ERROR: Failed getting image: ASI_ERROR_TIMEOUT (with 0.8 exposure = YES) (11)
Aug 22 09:36:26 allsky allsky[3132]: STARTING EXPOSURE at: 2024-08-22 09:36:26   @ 550 us (0.550 ms)
Aug 22 09:36:26 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=32, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:26 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: ERROR: flushBufferedImages() setControl() returned ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:26 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=550, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:31 allsky allsky[3132]:   > /home/pi/allsky/bin/capture_ZWO: ERROR: Failed getting image: ASI_ERROR_TIMEOUT (with 0.8 exposure = YES) (11)
Aug 22 09:36:33 allsky allsky[3132]: STARTING EXPOSURE at: 2024-08-22 09:36:33   @ 550 us (0.550 ms)
Aug 22 09:36:33 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=32, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:33 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: ERROR: flushBufferedImages() setControl() returned ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:33 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: WARNING: ASISetControlValue() for control 1, value=550, camNum=0, makeAuto=0 failed: ASI_ERROR_GENERAL_ERROR (16)
Aug 22 09:36:39 allsky allsky[3132]:   > /home/pi/allsky/bin/capture_ZWO: ERROR: Failed getting image: ASI_ERROR_TIMEOUT (with 0.8 exposure = YES) (11)
Aug 22 09:36:41 allsky allsky[3132]: *** /home/pi/allsky/bin/capture_ZWO: ERROR: Maximum number of consecutive errors of 5 reached; capture program exited.
Aug 22 09:36:44 allsky allsky[3132]:      ***** Stopping AllSky *****
Aug 22 09:36:44 allsky allsky[3010]: Stopping Allsky: Allsky Stopped!<br>Non-recoverable ERROR found<br>See /var/log/allsky.log.
Aug 22 09:36:45 allsky allsky[3010]:      ***** AllSky Stopped *****
Aug 22 09:38:27 allsky allsky[3648]:      ***** Starting AllSky *****
Aug 22 09:38:28 allsky allsky[3648]: *** FATAL ERROR: ZWO Camera not found and no USB entry either.
Aug 22 09:38:28 allsky allsky[3648]:   If you have the 'uhubctl' command installed, add it to config.sh.
Aug 22 09:38:28 allsky allsky[3648]:   In the meantime, try running it to reset the USB bus.
Aug 22 09:38:28 allsky allsky[3648]: Stopping Allsky: Unable to start Allsky!<br>FATAL ERROR: ZWO Camera not found<br>See /var/log/allsky.log.
Aug 22 09:38:29 allsky allsky[3648]:      ***** AllSky Stopped *****
Aug 22 09:38:29 allsky allsky[3744]:      ***** Starting AllSky *****
Aug 22 09:38:34 allsky allsky[3744]: *** FATAL ERROR: ZWO Camera not found and no USB entry either.
Aug 22 09:38:34 allsky allsky[3744]:   If you have the 'uhubctl' command installed, add it to config.sh.
Aug 22 09:38:34 allsky allsky[3744]:   In the meantime, try running it to reset the USB bus.
Aug 22 09:38:34 allsky allsky[3744]: Stopping Allsky: Unable to start Allsky!<br>FATAL ERROR: ZWO Camera not found<br>See /var/log/allsky.log.
Aug 22 09:38:34 allsky allsky[3744]:      ***** AllSky Stopped *****
pi@allsky:/var/log $

Since there have been similair issues before like this I have set Auto USB Bandwidth to No and USB Bandwidth to 80%.

I did now install uhubctl on the device, how would I activate it in Allsky?

EricClaeys commented 3 weeks ago

@WirthmU, ASI_ERROR_GENERAL_ERROR indicates a hardware problem - could be the camera itself, the USB cable, or the Pi. Is this a new camera?

Things to try:

  1. Is the cable plugged in tightly on both ends?
  2. Try the other three USB ports on the Pi.
  3. Try a new cable.
  4. In config.sh near the end are a couple UHUBCTL variables. One sets the path to the uhubctl program, e.g., /home/pi/uhubctl. The other is the port the camera is on. To be honest, I never figured this out and just use "2".
  5. Try using the camera on a PC. You'll probably need to download ZWO's software, but this is a great way to rule out the camera as a problem.
WirthmU commented 3 weeks ago

The system has been up and running for almost 3 years and it used to work for months in a row, same Pi, same camera, same cable. I do not think that the cables might be the problem or do they tend to degrade?

After installing UHUBCTL and upgrading to the latest Allsky the system has been running for almost 24 hours without any problems before it crashed again. It looks like UHUBCTL makes a slight difference.

EricClaeys commented 3 weeks ago

An easy way to check if it's the new Allsky is to try allsky-OLD if you still have it.

Other than a new Allsky, what else is different than what you had before?

Cables can go bad for no apparent reason.

WirthmU commented 3 weeks ago

The camera is installed in a remote location in a holiday house. I am a bit reluctant to take the system apart for testing. I guess I will rather try with UHUBCTL parameters and look wether this helps.

On my system lsusb shows ZWO ASI385MC on Bus 001 and Device 003. If I run UHUBTL it shows that the camera is attached to Port 1. Do you know how to power port 1 using UHUBCTL?

EricClaeys commented 3 weeks ago

Run: ./uhubctl --help It's something like 

./uhubctl --action off --exact --search 03C3:0
sleep 3
./uhubctl --action on --exact --search 03C3:0

Where 03C3 is the code for ZWO.

aaronwmorris commented 3 weeks ago

@WirthmU You have to think of your all sky system as being in a more "industrial" environment. It is subjected to repeated cooling/heating cycles daily of 20-30 degrees C delta. The metal contacts of the USB connection are physically expanding and contracting due to these changes. This temperature delta can also mechanically affect the wiring in the connector.

It is probably subjected to a more humid environment which can induce more oxidation in the connectors.

This can affect both the USB and power connectors. Reseating the connectors would probably fix both of these problems.

A bad power supply can cause these issues, too.

WirthmU commented 2 weeks ago

I totally agree @aaronwmorris these cameras are low-budget tech in an extremely harsh environment. I went through a number of iterations of camera and housing designs to find workarounds between heat and humidity. And even using the best components available the hardware would need service every once in a while - just like a car.

WirthmU commented 2 weeks ago

It still looks to me like it rather is a software than a hardware problem. I observed the loss of connection to the camera for several days now and it always happened between 9 and 10 am. And of course the allsky service went down with it. Today I did reset the USB port on the PI issuing uhubctl commands:

uhubctl -l 1-1 -p 1 -a off

and then about 30 seconds later

uhubctl -l 1-1 -p 1 -a on

The allsky service and current daytime picture immediately came back.

Do you think you can realize a corresponding watchdog routine in allsky or should this rather be run apart from it?

EricClaeys commented 2 weeks ago

@WirthmU, what would a watchdog timer do? If Allsky finds the uhubctl command it will automatically invoke it after 5 USB-related errors. I think it will do that two times, then give up. Did you set the UHUBCTL variables in config.sh?

Another think to try is changing the New Exposure Algorithm setting in the WebUI.

WirthmU commented 2 weeks ago

If it is already implemented in allsky there is no need for a watchdog.

I did set the following in config.sh

UHUBCTL_PATH="/usr/sbin/uhubctl"
UHUBCTL_PORT=1

New Exposure Algorithm is set to yes

This is what I got this morning:

Aug 27 09:39:41 allsky allsky[127730]: ==========
Aug 27 09:39:41 allsky allsky[127730]: === Starting daytime capture ===
Aug 27 09:39:41 allsky allsky[127730]: ==========
Aug 27 09:39:41 allsky allsky[127730]: STARTING EXPOSURE at: 2024-08-27 09:39:41   @ 100.00 ms (0.10 sec)
Aug 27 09:40:00 allsky allsky[127730]:      ***** Stopping AllSky *****
Aug 27 09:40:01 allsky allsky[127892]:      ***** Starting AllSky *****
Aug 27 09:40:02 allsky allsky[127892]: WARNING: Resetting USB ports looking for a ZWO camera, then restarting.
Aug 27 09:40:02 allsky allsky[127985]:      ***** Starting AllSky *****
Aug 27 09:40:02 allsky allsky[128007]:      ***** Starting AllSky *****
Aug 27 09:40:02 allsky allsky[128037]:      ***** Starting AllSky *****
Aug 27 09:40:07 allsky allsky[128073]:      ***** Starting AllSky *****
Aug 27 09:40:35 allsky allsky[128133]:      ***** Starting AllSky *****
Aug 27 09:40:42 allsky allsky[128254]: *** /home/pi/allsky/bin/capture_ZWO: ERROR: No Connected Camera...
Aug 27 09:40:45 allsky allsky[128254]:      ***** Stopping AllSky *****
Aug 27 09:40:45 allsky allsky[128133]: ***
Aug 27 09:40:45 allsky allsky[128133]: *** After fixing, restart the allsky service. ***
Aug 27 09:40:45 allsky allsky[128133]: ***
Aug 27 09:40:54 allsky allsky[128133]:      ***** AllSky Stopped *****

If I do interpret correctly, the command that is issued by allsky, if there is an USB connection failure, is: sudo /usr/sbin/uhubctl -a cycle -l 1 This gives:

pi@allsky:/var/log $ sudo /usr/sbin/uhubctl -a cycle -l 1
Current status for hub 1 [1d6b:0002 Linux 6.6.45-v8+ xhci-hcd xHCI Host Controller 0000:01:00.0, USB 2.00, 1 ports, ppps]
  Port 1: 0503 power highspeed enable connect [2109:3431 USB2.0 Hub, USB 2.10, 4 ports, ppps]
Sent power off request
New status for hub 1 [1d6b:0002 Linux 6.6.45-v8+ xhci-hcd xHCI Host Controller 0000:01:00.0, USB 2.00, 1 ports, ppps]
  Port 1: 0000 off
Current status for hub 1 [1d6b:0002 Linux 6.6.45-v8+ xhci-hcd xHCI Host Controller 0000:01:00.0, USB 2.00, 1 ports, ppps]
  Port 1: 0000 off
Sent power on request
New status for hub 1 [1d6b:0002 Linux 6.6.45-v8+ xhci-hcd xHCI Host Controller 0000:01:00.0, USB 2.00, 1 ports, ppps]
  Port 1: 0503 power highspeed enable connect [2109:3431]

And there is no re-connection to the camera.

The command that I am using in CLI is: sudo uhubctl -l 1-1 -p 1 -a off sudo uhubctl -l 1-1 -p 1 -a on or sudo uhubctl -l 1-1 -p 1 -a cycle

pi@allsky:/var/log $ sudo uhubctl -l 1-1 -p 1 -a cycle
Current status for hub 2 [1d6b:0003 Linux 6.6.45-v8+ xhci-hcd xHCI Host Controller 0000:01:00.0, USB 3.00, 4 ports, ppps]
  Port 1: 02a0 power 5gbps Rx.Detect
Sent power off request
New status for hub 2 [1d6b:0003 Linux 6.6.45-v8+ xhci-hcd xHCI Host Controller 0000:01:00.0, USB 3.00, 4 ports, ppps]
  Port 1: 0080 off
Current status for hub 1-1 [2109:3431 USB2.0 Hub, USB 2.10, 4 ports, ppps]
  Port 1: 0503 power highspeed enable connect [03c3:385b ZWO ASI385MC]
Sent power off request
New status for hub 1-1 [2109:3431 USB2.0 Hub, USB 2.10, 4 ports, ppps]
  Port 1: 0000 off
Current status for hub 2 [1d6b:0003 Linux 6.6.45-v8+ xhci-hcd xHCI Host Controller 0000:01:00.0, USB 3.00, 4 ports, ppps]
  Port 1: 0080 off
Sent power on request
New status for hub 2 [1d6b:0003 Linux 6.6.45-v8+ xhci-hcd xHCI Host Controller 0000:01:00.0, USB 3.00, 4 ports, ppps]
  Port 1: 02a0 power 5gbps Rx.Detect
Current status for hub 1-1 [2109:3431 USB2.0 Hub, USB 2.10, 4 ports, ppps]
  Port 1: 0000 off
Sent power on request
New status for hub 1-1 [2109:3431 USB2.0 Hub, USB 2.10, 4 ports, ppps]
  Port 1: 0101 power connect [03c3:385b]

After issuing this command the camera is up and working again.

Do you think the problem is the port ID (1 vs 1-1)?

EricClaeys commented 2 weeks ago

I have never been able to figure out how uhubctl's "location" and "port" map to what lsusb returns, which is how Allsky determines if a camera exists. And it doesn't seem to matter what arguments are passed to uhubctl since appears to power cycle everything. So I think your port of 1 is fine.

Next time the problem happens, run lsusb -d 03C3: which will list the ZWO devices. I still think this is a hardware issue.

aaronwmorris commented 2 weeks ago

The location and port mapping is very vague in lsusb, but I think lsusb tries to simplify the USB layout. The way hubs are chained together makes the tree very complicated. And a "hub" is not a physical hub, but the virtual hubs that are used to multiplex the ports.

If you plug in another [physical] USB hub, that might actually multiple USB hubs internally. I have a 10 port USB hub that is actually represented as 8 USB hub devices (4 USB3 and 4 USB2 hubs each with 4 ports) in uhubctl.

I would be very careful trying to do anything with uhubctl automatically. There is not requirement that a camera be plugged directly to the Pi (it could be connected to an external hub). Also, there may be other USB devices, such as USB wifi adapters that could get cycled.

I am with @EricClaeys... this is 100% a hardware issue.

EricClaeys commented 2 weeks ago

@aaronwmorris, in the next Allsky release allsky.sh only power cycles the port the ZWO camera is on:

SEARCH="${ZWO_VENDOR}:${ZWO_CAMERA_ID}"   # e.g., 03C3:385b
sudo "${ALLSKY_BIN}/uhubctl" --action off --exact --search "${SEARCH}"
sleep 3     # give it a few seconds, plus, allow the notification images to be seen
sudo "${ALLSKY_BIN}/uhubctl" --action on --exact --search "${SEARCH}"

Since ZWO's "snapshot" mode will be the default, there will be significantly fewer ASI_ERROR's so uhubctl will likely only be called for hardware problems.