search

Xinne / osc4py3

31 stars 6 forks source link

[CRITICAL] osc4py3 package stopped working `as_comthreads` since version `1.0.4` #11

Open vivi90 opened 2 years ago

vivi90 commented 2 years ago

Code

Using the code from an old closed issue as an example for testing:

#!/usr/bin/env python3
# -*- coding: utf-8 -*-

"""``osc4py3.as_comthreads`` example."""

# Logging
from logging import (
    basicConfig as set_logger_config,
    getLogger as get_logger,
    DEBUG as LOGLEVEL_DEBUG
)
FRM = "%(asctime)s - %(threadName)s ø %(name)s - %(levelname)s - %(message)s"
set_logger_config(
    filename="osc.log",
    filemode='a',
    encoding="utf-8",
    format=FRM
)
logger = get_logger("osc")
logger.setLevel(LOGLEVEL_DEBUG)

# ``osc4py3``
from osc4py3.as_comthreads import *
from osc4py3 import oscbuildparse
osc_startup(logger=logger)
# Make client channels to send packets.
osc_udp_client("127.0.0.1", 39540, "local")
# Build a simple message and send it.
msg = oscbuildparse.OSCMessage("/test/me", ",sif", ["text", 672, 8.871])
osc_send(msg, "local")
osc_process()
osc_terminate()

Problem

If iam replacing from osc4py3.as_comthreads import * by from osc4py3.as_eventloop import * it works as expected. But with as_comthreads it sends nothing. Also i get no error message without using logging. In the logging it seems to me, that it closes the channel before finished: 

[..] Failure in sendingpackets_process_loop() [..]
[..] RuntimeError: WorkQueue jobs terminated.

So seems related to issues https://github.com/Xinne/osc4py3/issues/4 and https://github.com/Xinne/osc4py3/issues/2.

Logs

With as_comthreads (not working)

2022-07-25 17:05:57,697 - MainThread ø osc - DEBUG - monitor 1852464819712 created (SelectSocketMonitor).
2022-07-25 17:05:57,700 - RawPackThread ø osc - INFO - OSC Starting rawpackets_process_loop()
2022-07-25 17:05:57,702 - SendPackThread ø osc - INFO - OSC Starting sendingpackets_process_loop()
2022-07-25 17:05:57,700 - SocketThread ø osc - INFO - OSC Monitoring thread started for monitor 1852464819712.
2022-07-25 17:05:57,702 - SocketThread ø osc - DEBUG - monitor 1852464819712 wait sockets(r[744] w[] e[] 60.0).
2022-07-25 17:05:57,703 - DelayThread ø osc - INFO - OSC Starting delayed_process_loop()
2022-07-25 17:05:57,704 - MainThread ø osc - INFO - OSC channel 'local' setup as writer.
2022-07-25 17:05:57,705 - MainThread ø osc - DEBUG - OSC opening channel 'local'.
2022-07-25 17:05:57,706 - MainThread ø osc - INFO - UDP channel 'local' open write on ('0.0.0.0', 0) target AddrInfo(family=<AddressFamily.AF_INET: 2>, socktype=<SocketKind.SOCK_DGRAM: 2>, proto=17, canonname='127.0.0.1:39540', sockaddr=('127.0.0.1', 39540)).
2022-07-25 17:05:57,706 - MainThread ø osc - INFO - OSC channel 'local' activated.
2022-07-25 17:05:57,706 - MainThread ø osc - DEBUG - OSC scheduling channel 'local'.
2022-07-25 17:05:57,706 - MainThread ø osc - INFO - OSC channel 'local' scheduled.
2022-07-25 17:05:57,707 - MainThread ø osc - DEBUG - OSC unscheduling channel 'local'.
2022-07-25 17:05:57,707 - SendPackThread ø osc - DEBUG - OSC send packets processing SendingPacket(packet=OSCMessage(addrpattern='/test/me', typetags=',sif', arguments=['text', 672, 8.871]), packopt=<osc4py3.oscpacketoptions.PacketOptions object at 0x000001AF4F89B040>, targets={'local'})
2022-07-25 17:05:57,707 - MainThread ø osc - INFO - OSC channel 'local' unscheduled.
2022-07-25 17:05:57,708 - SendPackThread ø osc - DEBUG - OSC packet_send_function to targets {'local'} with OSCMessage(addrpattern='/test/me', typetags=',sif', arguments=['text', 672, 8.871])
2022-07-25 17:05:57,708 - MainThread ø osc - DEBUG - OSC closing channel 'local'.
2022-07-25 17:05:57,708 - SendPackThread ø osc - DEBUG - OSC transmit_rawpacket to channels {'local'}
2022-07-25 17:05:57,708 - MainThread ø osc - INFO - UDP channel 'local' closed.
2022-07-25 17:05:57,708 - SendPackThread ø osc - DEBUG - OSC channel 'local' transmit_data via write_pending queue
2022-07-25 17:05:57,709 - MainThread ø osc - INFO - OSC channel 'local' deactivated.
2022-07-25 17:05:57,709 - SendPackThread ø osc - DEBUG - OSC channel 'local' another write packet available
2022-07-25 17:05:57,709 - MainThread ø osc - DEBUG - monitor 1852464819712 request to terminate.
2022-07-25 17:05:57,709 - SendPackThread ø osc - DEBUG - OSC channel 'local' schedule of packet to write
2022-07-25 17:05:57,709 - SendPackThread ø osc - ERROR - OSC Failure in sendingpackets_process_loop()
Traceback (most recent call last):
  File "C:\tools\miniconda3\envs\test\lib\site-packages\osc4py3\oscdistributing.py", line 284, in sendingpackets_process_loop
    packet_send_function(packet, packopt, targets, logger)
  File "C:\tools\miniconda3\envs\test\lib\site-packages\osc4py3\oscdistributing.py", line 198, in packet_send_function
    transmit_rawpacket(rawoscdata, packopt, stdchannels, logger)
  File "C:\tools\miniconda3\envs\test\lib\site-packages\osc4py3\oscdistributing.py", line 236, in transmit_rawpacket
    chanel.transmit_data(rawpacket, newopt)
  File "C:\tools\miniconda3\envs\test\lib\site-packages\osc4py3\oscchannel.py", line 776, in transmit_data
    self.schedule_write_packet()
  File "C:\tools\miniconda3\envs\test\lib\site-packages\osc4py3\oscchannel.py", line 843, in schedule_write_packet
    self.write_workqueue.send_callable(self.write_operation, ())
  File "C:\tools\miniconda3\envs\test\lib\site-packages\osc4py3\osctoolspools.py", line 138, in send_callable
    self.send_job(job)
  File "C:\tools\miniconda3\envs\test\lib\site-packages\osc4py3\osctoolspools.py", line 153, in send_job
    raise RuntimeError("WorkQueue jobs terminated.")
RuntimeError: WorkQueue jobs terminated.
2022-07-25 17:05:57,710 - SocketThread ø osc - INFO - monitor 1852464819712 terminating.
2022-07-25 17:05:57,730 - RawPackThread ø osc - INFO - OSC Finishing rawpackets_process_loop()
2022-07-25 17:05:57,730 - SocketThread ø osc - INFO - OSC Monitoring thread terminated for monitor 1852464819712.
2022-07-25 17:05:57,730 - DelayThread ø osc - INFO - OSC Finishing delayed_process_loop()

With as_eventloop (working)

2022-07-25 17:17:11,681 - MainThread ø osc - DEBUG - monitor 2720311868816 created (SelectSocketMonitor).
2022-07-25 17:17:11,682 - MainThread ø osc - INFO - OSC channel 'local' setup as writer.
2022-07-25 17:17:11,683 - MainThread ø osc - DEBUG - OSC opening channel 'local'.
2022-07-25 17:17:11,683 - MainThread ø osc - INFO - UDP channel 'local' open write on ('0.0.0.0', 0) target AddrInfo(family=<AddressFamily.AF_INET: 2>, socktype=<SocketKind.SOCK_DGRAM: 2>, proto=17, canonname='127.0.0.1:39540', sockaddr=('127.0.0.1', 39540)).
2022-07-25 17:17:11,683 - MainThread ø osc - INFO - OSC channel 'local' activated.
2022-07-25 17:17:11,684 - MainThread ø osc - DEBUG - OSC scheduling channel 'local'.
2022-07-25 17:17:11,684 - MainThread ø osc - INFO - OSC channel 'local' scheduled.
2022-07-25 17:17:11,684 - MainThread ø osc - DEBUG - OSC send packets processing SendingPacket(packet=OSCMessage(addrpattern='/test/me', typetags=',sif', arguments=['text', 672, 8.871]), packopt=<osc4py3.oscpacketoptions.PacketOptions object at 0x000002795F40E0B0>, targets={'local'})
2022-07-25 17:17:11,684 - MainThread ø osc - DEBUG - OSC packet_send_function to targets {'local'} with OSCMessage(addrpattern='/test/me', typetags=',sif', arguments=['text', 672, 8.871])
2022-07-25 17:17:11,685 - MainThread ø osc - DEBUG - OSC transmit_rawpacket to channels {'local'}
2022-07-25 17:17:11,685 - MainThread ø osc - DEBUG - OSC channel 'local' transmit_data via write_pending queue
2022-07-25 17:17:11,685 - MainThread ø osc - DEBUG - OSC channel 'local' another write packet available
2022-07-25 17:17:11,685 - MainThread ø osc - DEBUG - OSC channel 'local' schedule of packet to write
2022-07-25 17:17:11,685 - MainThread ø osc - DEBUG - UDP sendto(bytearray(b'/test/me\x00\x00\x00\x00,sif\x00\x00\x00\x00text\x00\x00\x00\x00\x00\x00\x02\xa0A\r\xef\x9e') (...), ('127.0.0.1', 39540))
2022-07-25 17:17:11,686 - MainThread ø osc - DEBUG - OSC channel 'local' monitoring set to True
2022-07-25 17:17:11,686 - MainThread ø osc - DEBUG - monitor 2720311868816 req add channel 748->local for w.
2022-07-25 17:17:11,686 - MainThread ø osc - INFO - monitor 2720311868816 added channel local for w.
2022-07-25 17:17:11,686 - MainThread ø osc - DEBUG - monitor 2720311868816 detected w on channel local.
2022-07-25 17:17:11,686 - MainThread ø osc - DEBUG - UDP channel 'local' trigged for transmissions. w
2022-07-25 17:17:11,687 - MainThread ø osc - DEBUG - OSC channel 'local' notification of written packet
2022-07-25 17:17:11,687 - MainThread ø osc - DEBUG - OSC channel 'local' monitoring set to False
2022-07-25 17:17:11,687 - MainThread ø osc - DEBUG - monitor 2720311868816 request to remove channel local for w.
2022-07-25 17:17:11,687 - MainThread ø osc - DEBUG - OSC unscheduling channel 'local'.
2022-07-25 17:17:11,687 - MainThread ø osc - INFO - OSC channel 'local' unscheduled.
2022-07-25 17:17:11,688 - MainThread ø osc - DEBUG - OSC closing channel 'local'.
2022-07-25 17:17:11,688 - MainThread ø osc - INFO - UDP channel 'local' closed.
2022-07-25 17:17:11,688 - MainThread ø osc - INFO - OSC channel 'local' deactivated.
2022-07-25 17:17:11,688 - MainThread ø osc - DEBUG - monitor 2720311868816 request to terminate.

System

vivi90 commented 2 years ago

Code (with time delay)

An time delay solves only the error message in the logs but still nothing is sent 🙁 

#!/usr/bin/env python3
# -*- coding: utf-8 -*-

"""``osc4py3.as_comthreads`` example."""

from time import sleep
# Logging
from logging import (
    basicConfig as set_logger_config,
    getLogger as get_logger,
    DEBUG as LOGLEVEL_DEBUG
)
FRM = "%(asctime)s - %(threadName)s ø %(name)s - %(levelname)s - %(message)s"
set_logger_config(
    filename="osc.log",
    filemode='a',
    encoding="utf-8",
    format=FRM
)
logger = get_logger("osc")
logger.setLevel(LOGLEVEL_DEBUG)

# ``osc4py3``
from osc4py3.as_comthreads import *
from osc4py3 import oscbuildparse
osc_startup(logger=logger)
# Make client channels to send packets.
osc_udp_client("127.0.0.1", 39540, "local")
# Build a simple message and send it.
msg = oscbuildparse.OSCMessage("/test/me", ",sif", ["text", 672, 8.871])
osc_send(msg, "local")
osc_process()
sleep(5)
osc_process()
osc_terminate()

Logs

2022-07-25 17:41:10,372 - MainThread ø osc - DEBUG - monitor 2255519411712 created (SelectSocketMonitor).
2022-07-25 17:41:10,375 - RawPackThread ø osc - INFO - OSC Starting rawpackets_process_loop()
2022-07-25 17:41:10,376 - SendPackThread ø osc - INFO - OSC Starting sendingpackets_process_loop()
2022-07-25 17:41:10,375 - SocketThread ø osc - INFO - OSC Monitoring thread started for monitor 2255519411712.
2022-07-25 17:41:10,377 - SocketThread ø osc - DEBUG - monitor 2255519411712 wait sockets(r[744] w[] e[] 60.0).
2022-07-25 17:41:10,378 - DelayThread ø osc - INFO - OSC Starting delayed_process_loop()
2022-07-25 17:41:10,379 - MainThread ø osc - INFO - OSC channel 'local' setup as writer.
2022-07-25 17:41:10,380 - MainThread ø osc - DEBUG - OSC opening channel 'local'.
2022-07-25 17:41:10,380 - MainThread ø osc - INFO - UDP channel 'local' open write on ('0.0.0.0', 0) target AddrInfo(family=<AddressFamily.AF_INET: 2>, socktype=<SocketKind.SOCK_DGRAM: 2>, proto=17, canonname='127.0.0.1:39540', sockaddr=('127.0.0.1', 39540)).
2022-07-25 17:41:10,381 - MainThread ø osc - INFO - OSC channel 'local' activated.
2022-07-25 17:41:10,381 - MainThread ø osc - DEBUG - OSC scheduling channel 'local'.
2022-07-25 17:41:10,381 - MainThread ø osc - INFO - OSC channel 'local' scheduled.
2022-07-25 17:41:10,381 - SendPackThread ø osc - DEBUG - OSC send packets processing SendingPacket(packet=OSCMessage(addrpattern='/test/me', typetags=',sif', arguments=['text', 672, 8.871]), packopt=<osc4py3.oscpacketoptions.PacketOptions object at 0x0000020D2776B040>, targets={'local'})
2022-07-25 17:41:10,382 - SendPackThread ø osc - DEBUG - OSC packet_send_function to targets {'local'} with OSCMessage(addrpattern='/test/me', typetags=',sif', arguments=['text', 672, 8.871])
2022-07-25 17:41:10,382 - SendPackThread ø osc - DEBUG - OSC transmit_rawpacket to channels {'local'}
2022-07-25 17:41:10,382 - SendPackThread ø osc - DEBUG - OSC channel 'local' transmit_data via write_pending queue
2022-07-25 17:41:10,383 - SendPackThread ø osc - DEBUG - OSC channel 'local' another write packet available
2022-07-25 17:41:10,383 - SendPackThread ø osc - DEBUG - OSC channel 'local' schedule of packet to write
2022-07-25 17:41:15,381 - MainThread ø osc - DEBUG - OSC unscheduling channel 'local'.
2022-07-25 17:41:15,381 - MainThread ø osc - INFO - OSC channel 'local' unscheduled.
2022-07-25 17:41:15,381 - MainThread ø osc - DEBUG - OSC closing channel 'local'.
2022-07-25 17:41:15,381 - MainThread ø osc - INFO - UDP channel 'local' closed.
2022-07-25 17:41:15,381 - MainThread ø osc - INFO - OSC channel 'local' deactivated.
2022-07-25 17:41:15,382 - MainThread ø osc - DEBUG - monitor 2255519411712 request to terminate.
2022-07-25 17:41:15,382 - SendPackThread ø osc - INFO - OSC Finishing sendingpackets_process_loop()
2022-07-25 17:41:15,382 - SocketThread ø osc - INFO - monitor 2255519411712 terminating.
2022-07-25 17:41:15,383 - RawPackThread ø osc - INFO - OSC Finishing rawpackets_process_loop()
2022-07-25 17:41:15,383 - SocketThread ø osc - INFO - OSC Monitoring thread terminated for monitor 2255519411712.
2022-07-25 17:41:15,383 - DelayThread ø osc - INFO - OSC Finishing delayed_process_loop()

System

vivi90 commented 2 years ago

Workaround

With version 1.0.1 and 1.0.3 it works perfectly fine. It's broken since 1.0.4 like mentioned in https://github.com/Xinne/osc4py3/issues/4#issuecomment-409595319.

$ pip install osc4py3==1.0.3

Please fix this issue, if possible 🙂