Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

usb3: multithreading causes mixup in libusb responses #622

Closed
TIS-Edgar opened this issue Jan 31, 2022 · 7 comments
Closed

usb3: multithreading causes mixup in libusb responses #622

TIS-Edgar opened this issue Jan 31, 2022 · 7 comments

Comments

@TIS-Edgar
Copy link
Contributor

Describe the bug

When using a USB3 camera in a complex multi-threaded application a reliable timeout of libusb ack packages can be achieved.

This causes the camera to ignore commands or the application to behave in unexpected ways.
In my case it reliably prevents a stream start.

Excerpt of log output with ARV_DEBUG=all:3 and arvuvdevice.c modified for more debugging information:


[11:56:22.049] 🅳 cp> flags        = 0x4000
                     command      = read-memory-cmd
                     size         = 12
                     id           = 1731
                     address      = 0x4c525443cc000900
                     size         =          4 (0x00000004)
                     00000000 55 33 56 43 00 40 00 08 0c 00 c3 06 00 09 00 cc  U3VC.@..........
                     00000010 43 54 52 4c 00 00 04 00                          CTRL....        
[11:56:22.050] 🅳 genicam> [GcRegisterNode::_set_integer_value] address = 0x4c525443f0f00614, value = 0x2
[11:56:22.050] 🅳 cp> flags        = 0x4000
                     command      = write-memory-cmd
                     size         = 12
                     id           = 1732
                     address      = 0x4c525443f0f00614
                     00000000 55 33 56 43 00 40 02 08 0c 00 c4 06 14 06 f0 f0  U3VC.@..........
                     00000010 43 54 52 4c 02 00 00 00                          CTRL....        
[11:56:22.050] 🅳 cp> status       = success
                     command      = read-memory-ack
                     size         = 4
                     id           = 1731
                     00000000 55 33 56 43 00 00 01 08 04 00 c3 06 00 00 00 00  U3VC............
[11:56:22.050] 🅸 device> [[UvDevice::read_memory] Unexpected answer (0x0000) - ack: 2049 - exp-ack: 2049 - packet: 1731 - exp packet: 1732
[11:56:22.050] 🅳 cp> status       = success
                     command      = write-memory-ack
                     size         = 4
                     id           = 1732
                     written      =          4 (0x00000004)
                     00000000 55 33 56 43 00 00 03 08 04 00 c4 06 00 00 04 00  U3VC............
[11:56:22.050] 🅳 genicam> [GcCommand::execute] AcquisitionStop (0x2)
[11:56:22.050] 🅳 cp> flags        = 0x4000
                     command      = read-memory-cmd
                     size         = 12
                     id           = 1733
                     address      = 0x4c525443cc000310
                     size         =          4 (0x00000004)
                     00000000 55 33 56 43 00 40 00 08 0c 00 c5 06 10 03 00 cc  U3VC.@..........
                     00000010 43 54 52 4c 00 00 04 00                          CTRL....        
[11:56:22.051] 🅳 cp> status       = success
                     command      = read-memory-ack
                     size         = 4
                     id           = 1733
                     00000000 55 33 56 43 00 00 01 08 04 00 c5 06 00 00 00 00  U3VC............
[11:56:22.051] 🅳 genicam> [GcRegisterNode::_get_integer_value] address = 0x4c525443cc000900, value = 0x0
[11:56:22.051] 🅳 cp> flags        = 0x4000
                     command      = read-memory-cmd
                     size         = 12
                     id           = 1734
                     address      = 0x4c525443cc000900
                     size         =          4 (0x00000004)
                     00000000 55 33 56 43 00 40 00 08 0c 00 c6 06 00 09 00 cc  U3VC.@..........
                     00000010 43 54 52 4c 00 00 04 00                          CTRL....        
[11:56:22.051] 🅳 cp> status       = success
                     command      = read-memory-ack
                     size         = 4
                     id           = 1734
                     00000000 55 33 56 43 00 00 01 08 04 00 c6 06 00 00 00 00  U3VC............
[11:56:22.051] 🅳 genicam> [GcRegisterNode::_get_integer_value] address = 0x4c525443cc000310, value = 0x0
[11:56:22.051] 🅳 genicam> [GcEnumeration::get_string_value] value = 0 - string = FrameStart
[11:56:22.051] 🅳 cp> flags        = 0x4000
                     command      = read-memory-cmd
                     size         = 12
                     id           = 1735
                     address      = 0x4c525443cc000030
                     size         =          4 (0x00000004)
                     00000000 55 33 56 43 00 40 00 08 0c 00 c7 06 30 00 00 cc  U3VC.@......0...
                     00000010 43 54 52 4c 00 00 04 00                          CTRL....        
[11:56:22.052] 🅳 cp> status       = success
                     command      = read-memory-ack
                     size         = 4
                     id           = 1735
                     00000000 55 33 56 43 00 00 01 08 04 00 c7 06 00 00 00 00  U3VC............
[11:56:22.052] 🅳 genicam> [GcRegisterNode::_get_integer_value] address = 0x4c525443cc000900, value = 0x0
[11:56:22.052] 🅳 cp> flags        = 0x4000
                     command      = read-memory-cmd
                     size         = 12
                     id           = 1736
                     address      = 0x4c525443cc000900
                     size         =          4 (0x00000004)
                     00000000 55 33 56 43 00 40 00 08 0c 00 c8 06 00 09 00 cc  U3VC.@..........
                     00000010 43 54 52 4c 00 00 04 00                          CTRL....        
[11:56:22.052] 🅳 cp> status       = success
                     command      = read-memory-ack
                     size         = 4
                     id           = 1736
                     00000000 55 33 56 43 00 00 01 08 04 00 c8 06 00 00 00 00  U3VC............
[11:56:22.052] 🅳 genicam> [GcRegisterNode::_get_integer_value] address = 0x4c525443cc000030, value = 0x0
[11:56:22.052] 🅳 genicam> [GcEnumeration::get_string_value] value = 0 - string = Off
[11:56:22.052] 🅳 genicam> [GcEnumeration::set_string_value] value = 0 - string = FrameStart
[11:56:22.052] 🅳 genicam> [GcRegisterNode::_set_integer_value] address = 0x4c525443cc000310, value = 0x0
[11:56:22.052] 🅳 cp> flags        = 0x4000
                     command      = write-memory-cmd
                     size         = 12
                     id           = 1737
                     address      = 0x4c525443cc000310
                     00000000 55 33 56 43 00 40 02 08 0c 00 c9 06 10 03 00 cc  U3VC.@..........
                     00000010 43 54 52 4c 00 00 00 00                          CTRL....        
[11:56:22.053] 🅳 cp> status       = success
                     command      = write-memory-ack
                     size         = 4
                     id           = 1737
                     written      =          4 (0x00000004)
                     00000000 55 33 56 43 00 00 03 08 04 00 c9 06 00 00 04 00  U3VC............
[11:56:22.053] 🅸 device> [[UvDevice::read_memory] Unexpected answer1 (0x0000) - ack: 2051 - exp-ack: 2049 - packet: 1737 - exp packet: 1737
[11:56:22.352] 🆆 device> [UvDevice::read_memory] Ack reception error: LIBUSB_ERROR_TIMEOUT
[11:56:22.352] 🆆 device> [UvDevice::write_memory] Ack reception error: LIBUSB_ERROR_TIMEOUT
[11:56:22.652] 🆆 device> [UvDevice::read_memory] Ack reception error: LIBUSB_ERROR_TIMEOUT

To Reproduce
In theory every application that simultaneously starts a stream and queries properties should exhibit this behavior.
arv-viewer-0.8 behaves fine.
tcam-capture on our development branch shows this behavior reliably.

Expected behavior
Correct association between cmd and ack.

Camera description:
Tested with multiple TIS USB3 cameras.

Platform description:

  • Aravis version:
    Current master (b8af426)

  • OS: [e.g. Fedora 20]
    Tested on Debian testing

  • Hardware [e.g. x86_64]
    amd64

Additional context

We were able to fix this by locking the loop in arvuvdevice.c _send_cmd_and_receive_ack with an additional mutex.
This prevented any miscommunication between cmds/acks and seems to solve the issue.

Since I am uncertain if this is a sufficient solution, I thought a bug report might be warranted.
@EmmanuelP
Copy link
Contributor

Hi Edgar,

Thanks for the report.

Does it also happen when async usb mode is enabled ?

Could you open a merge request with your fix in arvuvdevice.c ?

@TIS-Edgar TIS-Edgar mentioned this issue Feb 2, 2022
Merged
@TIS-Edgar
Copy link
Contributor Author

Hi Emmanuel,

I just verified it again. The bug happens with sync and async.

Merge request has been opened.

@EmmanuelP
Copy link
Contributor

My understanding is the message mixup should not happen if a device is only accessed by the same thread.

Aravis is not thread safe, and once a camera is instantiated, it should only be manipulated by a single thread, as well as its underlying objects (device, stream).

Anyway, as it can not hurt, I have applied your merge request to main.

@TIS-Edgar
Copy link
Contributor Author

You are correct, this only happens in multi threaded applications. But as it is, things happen and better safe than sorry.

Thanks for the merge! Take care.

@EmmanuelP EmmanuelP reopened this Feb 7, 2022
@EmmanuelP
Copy link
Contributor

Hi @TIS-Edgar

I'm reopening this issue as may be a global mutex is overkill. Could you check merge request #625, which uses an instance mutex ?

@TIS-Edgar
Copy link
Contributor Author

Just tested your commit. Everything seems to work correctly.

@EmmanuelP
Copy link
Contributor

Ok. Thanks Edgar.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@EmmanuelP @TIS-Edgar