search

Sixthhokage2 / remuco

Automatically exported from code.google.com/p/remuco
1 stars 1 forks source link

Crash when setting up Bluetooth - "error: (93, 'Protocol not supported')" #170

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
What is your environment?
* OS: Gentoo Linux
* Remuco version: 0.9.5
* Client device: Motorlola KRZR K1
* Player: mpd, vlc, mplayer

What steps will reproduce the problem?
1. Run remuco-mpd / remuco-mplayer / remuco-vlc 
2. remuco-mpd / remuco-mplayer crashes directly (remuco-vlc does not stop, but 
have the same error in log).
3.Client cannot connect to all of them (obviously after stop).

What is the expected behavior? What happens instead?
Client can connect to the player

I hope you have any idea, the logs:

Additional information:

$ cat .cache/remuco/mpd.log 
2011-08-21 21:49:59,466 [   INFO] [  config.py  218] remuco version: 0.9.5
2011-08-21 21:49:59,468 [   INFO] [   files.py   73] file browser root dirs: 
{'Linux': '/home/linux'} 
2011-08-21 21:49:59,496 [   INFO] [ manager.py   57] start player adapter
2011-08-21 21:49:59,501 [  ERROR] [ manager.py   64] ** BUG ** (93, 'Protocol 
not supported')
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/remuco/manager.py", line 59, in _start_pa
    pa.start()
  File "/usr/bin/remuco-mpd-2.7", line 98, in start
    remuco.PlayerAdapter.start(self)
  File "/usr/lib64/python2.7/site-packages/remuco/adapter.py", line 531, in start
    self.__info, self.__handle_message, self.config)
  File "/usr/lib64/python2.7/site-packages/remuco/net.py", line 415, in __init__
    self._sock = self._create_socket()
  File "/usr/lib64/python2.7/site-packages/remuco/net.py", line 495, in _create_socket
    sock = bluetooth.BluetoothSocket(bluetooth.RFCOMM)
  File "/usr/lib64/python2.7/site-packages/bluetooth/bluez.py", line 117, in __init__
    _sock = _bt.btsocket (proto)
error: (93, 'Protocol not supported')
2011-08-21 21:49:59,505 [   INFO] [ manager.py   73] stop player adapter
2011-08-21 21:49:59,506 [   INFO] [ manager.py   79] player adapter stopped

$cat .cache/remuco/mplayer.log 
2011-08-21 21:54:48,986 [   INFO] [  config.py  218] remuco version: 0.9.5
2011-08-21 21:54:48,988 [   INFO] [   files.py   73] file browser root dirs: 
{'Linux': '/home/linux'} 
2011-08-21 21:54:49,027 [   INFO] [ manager.py   57] start player adapter
2011-08-21 21:54:49,032 [  ERROR] [ manager.py   64] ** BUG ** (93, 'Protocol 
not supported')
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/remuco/manager.py", line 59, in _start_pa
    pa.start()
  File "/usr/bin/remuco-mplayer-2.7", line 116, in start
    remuco.PlayerAdapter.start(self)
  File "/usr/lib64/python2.7/site-packages/remuco/adapter.py", line 531, in start
    self.__info, self.__handle_message, self.config)
  File "/usr/lib64/python2.7/site-packages/remuco/net.py", line 415, in __init__
    self._sock = self._create_socket()
  File "/usr/lib64/python2.7/site-packages/remuco/net.py", line 495, in _create_socket
    sock = bluetooth.BluetoothSocket(bluetooth.RFCOMM)
  File "/usr/lib64/python2.7/site-packages/bluetooth/bluez.py", line 117, in __init__
    _sock = _bt.btsocket (proto)
error: (93, 'Protocol not supported')
2011-08-21 21:54:49,037 [   INFO] [ manager.py   73] stop player adapter
2011-08-21 21:54:49,037 [  ERROR] [ manager.py   77] ** BUG ** an integer is 
required
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/remuco/manager.py", line 75, in _stop_pa
    pa.stop()
  File "/usr/bin/remuco-mplayer-2.7", line 145, in stop
    os.closerange(self.fd_cmd_stream_in, self.fd_status_stream_out)
TypeError: an integer is required

$cat .cache/remuco/vlc.log 
2011-08-21 21:50:21,515 [   INFO] [  config.py  218] remuco version: 0.9.5
2011-08-21 21:50:21,516 [   INFO] [   files.py   73] file browser root dirs: 
{'Linux': '/home/linux'} 
2011-08-21 21:50:21,544 [   INFO] [ manager.py  251] start dbus observer
2011-08-21 21:50:21,548 [   INFO] [ manager.py  282] start main loop
2011-08-21 21:50:21,552 [   INFO] [ manager.py   57] start player adapter
2011-08-21 21:50:21,557 [  ERROR] [ manager.py   64] ** BUG ** (93, 'Protocol 
not supported')
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/remuco/manager.py", line 59, in _start_pa
    pa.start()
  File "/usr/bin/remuco-vlc-2.7", line 51, in start
    remuco.MPRISAdapter.start(self)
  File "/usr/lib64/python2.7/site-packages/remuco/mpris.py", line 125, in start
    PlayerAdapter.start(self)
  File "/usr/lib64/python2.7/site-packages/remuco/adapter.py", line 531, in start
    self.__info, self.__handle_message, self.config)
  File "/usr/lib64/python2.7/site-packages/remuco/net.py", line 415, in __init__
    self._sock = self._create_socket()
  File "/usr/lib64/python2.7/site-packages/remuco/net.py", line 495, in _create_socket
    sock = bluetooth.BluetoothSocket(bluetooth.RFCOMM)
  File "/usr/lib64/python2.7/site-packages/bluetooth/bluez.py", line 117, in __init__
    _sock = _bt.btsocket (proto)
error: (93, 'Protocol not supported')
2011-08-21 22:12:05,844 [   INFO] [ manager.py   73] stop player adapter
2011-08-21 22:12:05,844 [   INFO] [ manager.py   79] player adapter stopped
2011-08-21 22:12:16,447 [   INFO] [ manager.py   46] received signal 2
2011-08-21 22:12:16,447 [   INFO] [ manager.py  288] main loop stopped
2011-08-21 22:12:16,448 [   INFO] [ manager.py  292] observer stopped
2011-08-21 22:12:16,448 [   INFO] [ manager.py   73] stop player adapter
2011-08-21 22:12:16,449 [   INFO] [ manager.py   79] player adapter stopped

Original issue reported on code.google.com by jbuec...@gmail.com on 21 Aug 2011 at 8:18

GoogleCodeExporter commented 9 years ago 
Ok, found the problem.
I had to enable BT_RFCOMM in the kernel (and as module, I had to do a "modprobe 
rfcomm")

This is not a remuco bug (but may remuco can test this and give a warning after 
starting a player-adapter and a better message in the logs)

Thanks.

Original comment by jbuec...@gmail.com on 28 Aug 2011 at 10:24

GoogleCodeExporter commented 9 years ago 
Good news. But you're right, this kind of error currently is not handled 
properly (basically because Remuco expected an IOError exception but in your 
case some unexpected low-level Bluetooth-specific error has been raised).

Original comment by obensonne@googlemail.com on 29 Aug 2011 at 6:59

GoogleCodeExporter commented 9 years ago 
This issue was updated by revision 8377d4eba5ef.

Internal Bluetooth errors (which are not typed BluetoothError) shouldn't
be a problem anymore.

Original comment by obensonne@googlemail.com on 29 Aug 2011 at 7:29

GoogleCodeExporter commented 9 years ago 
@jbuec... could you please test the fix in case you still have the rfcomm-free 
kernel?

Original comment by obensonne@googlemail.com on 29 Aug 2011 at 7:36

GoogleCodeExporter commented 9 years ago 
I only blacklisted my rfcomm module and I can reproduce it with 0.9.5.

With newer hg its similar, the only difference is that I used a gentoo ebuild 
in the first case. 
Now I compiled it simply with make install-mpd like the documentation says.

$hg log | grep "Mon Aug 29"
Datum:           Mon Aug 29 21:26:10 2011 +0200
Datum:           Mon Aug 29 21:26:09 2011 +0200henrinde.htm

$make install-mpd

$remuco-mpd 
Log output will be stored in /home/linux/.cache/remuco/mpd.log
Contribute to Remuco: Please run 'remuco-report' once a client has connected, 
thanks!

$cat .cache/remuco/mpd.log 
2011-08-29 22:22:58,205 [   INFO] [  config.py  218] remuco version: 0.9.5
2011-08-29 22:22:58,205 [  DEBUG] [ adapter.py 1518] flags: 140F0E1F
2011-08-29 22:22:58,206 [   INFO] [   files.py   73] file browser root dirs: 
{'Linux': '/home/linux'} 
2011-08-29 22:22:58,251 [  DEBUG] [ adapter.py  516] init done
2011-08-29 22:22:58,252 [  DEBUG] [ remuco-mpd   85] MPD is at localhost:6600
2011-08-29 22:22:58,252 [   INFO] [ manager.py   57] start player adapter
2011-08-29 22:22:58,429 [  ERROR] [ manager.py   64] ** BUG ** (93, 'Protocol 
not supported')
Traceback (most recent call last):
  File "/usr/lib64/python2.7/site-packages/remuco/manager.py", line 59, in _start_pa
    pa.start()
  File "/usr/bin/remuco-mpd", line 98, in start
    remuco.PlayerAdapter.start(self)
  File "/usr/lib64/python2.7/site-packages/remuco/adapter.py", line 535, in start
    self.__info, self.__handle_message, self.config)
  File "/usr/lib64/python2.7/site-packages/remuco/net.py", line 414, in __init__
    self._sock = self._create_socket()
  File "/usr/lib64/python2.7/site-packages/remuco/net.py", line 508, in _create_socket
    raise e
error: (93, 'Protocol not supported')
2011-08-29 22:22:58,431 [   INFO] [ manager.py   73] stop player adapter
2011-08-29 22:22:58,431 [  DEBUG] [ adapter.py  593] stop done
2011-08-29 22:22:58,431 [  DEBUG] [ remuco-mpd  120] MPD adapter stopped
2011-08-29 22:22:58,431 [   INFO] [ manager.py   79] player adapter stopped

BTW. Is it possible to build a version without make install, but local in the 
source directory? Then no root is needed to test those things. And I don't need 
it beside my package manager.

greetings 
Jan

Original comment by jbuec...@gmail.com on 29 Aug 2011 at 8:35

GoogleCodeExporter commented 9 years ago 
This issue was updated by revision 668b1353e9ce.

Fixed (hopefully) the exception handling when the bluetooth module
throws an internal error (i.e. not BluetoothError).

Original comment by obensonne@googlemail.com on 29 Aug 2011 at 8:50

GoogleCodeExporter commented 9 years ago 
Okay, I hope it's working now (working means, the error is caught correctly).

Supposed your are in the root of the extracted Remuco source package, you can 
run an adapter (here: mpd) without installing it with the command:

    $ PYTHONPATH=base/module:$PYTHONPATH adapter/mpd/remuco-mpd

Cheers,
Oben

Original comment by obensonne@googlemail.com on 29 Aug 2011 at 8:54

GoogleCodeExporter commented 9 years ago 
Ok, I think the exception handling works, but I don't like it. Before it, the 
app crashes in bluez. Thats the reason I get the idea that this has nothing to 
do with remuco. I tried a simple script from the pybluez webside that crushed 
with the same error.

With the new error the app does not exit and the end looks like its all ok. As 
a normal user I wondering whats wrong... I thought that I get something like: 
"rfcomm missing" (maybe the dependencies / GetStarted webside should be 
updated, too). Without rfcomm, the player adapter should exit to make clear 
here is a server problem.

cat .cache/remuco/mpd.log 
2011-08-29 22:58:31,517 [   INFO] [  config.py  218] remuco version: 0.9.5
2011-08-29 22:58:31,518 [  DEBUG] [ adapter.py 1518] flags: 140F0E1F
2011-08-29 22:58:31,518 [   INFO] [   files.py   73] file browser root dirs: 
{'Linux': '/home/linux'} 
2011-08-29 22:58:31,543 [  DEBUG] [ adapter.py  516] init done
2011-08-29 22:58:31,544 [  DEBUG] [ remuco-mpd   85] MPD is at localhost:6600
2011-08-29 22:58:31,544 [   INFO] [ manager.py   57] start player adapter
2011-08-29 22:58:31,551 [  ERROR] [     net.py  418] failed to set up bluetooth 
server ([Errno 93] Protocol not supported)
2011-08-29 22:58:31,552 [  DEBUG] [   remos.py  181] publishing zeroconf service
2011-08-29 22:58:31,557 [WARNING] [   remos.py  192] failed to publish zeroconf 
service (org.freedesktop.DBus.Error.ServiceUnknown: The name 
org.freedesktop.Avahi was not provided by any .service files)
2011-08-29 22:58:31,557 [   INFO] [     net.py  421] created wifi server
2011-08-29 22:58:31,557 [  DEBUG] [ adapter.py  548] poll every 2500 milli 
seconds
2011-08-29 22:58:31,557 [  DEBUG] [ adapter.py  552] start done
2011-08-29 22:58:31,559 [  DEBUG] [ remuco-mpd  560] connected to MPD
2011-08-29 22:58:31,559 [   INFO] [ remuco-mpd  109] MPD version: 0.16.0
2011-08-29 22:58:31,559 [   INFO] [ manager.py   67] player adapter started
2011-08-29 22:58:31,559 [   INFO] [ manager.py  282] start main loop
2011-08-29 22:58:34,060 [  DEBUG] [ adapter.py 1199] trigger for __sync_state 
already active
2011-08-29 22:58:34,061 [  DEBUG] [ adapter.py 1199] trigger for __sync_state 
already active
2011-08-29 22:58:34,062 [  DEBUG] [     art.py   82] looking for art image in 
XXX
2011-08-29 22:58:34,062 [  DEBUG] [ adapter.py  645] image for 'XXX/XXX/XXX': 
None
2011-08-29 22:58:34,063 [  DEBUG] [ adapter.py 1177] new item: (XXX/XXX - XXX - 
XXX, {'album': '21', 'title': 'XXX', 'artist': 'XXX', 'length': '224', 'year': 
None, 'genre': 'Pop'} None)
2011-08-29 22:58:34,063 [  DEBUG] [ adapter.py 1209] broadcast new state to 
clients: (0, 100, 3, True, False, False)
2011-08-29 22:58:34,063 [  DEBUG] [ adapter.py 1239] broadcast new item to 
clients: XXX

Original comment by jbuec...@gmail.com on 29 Aug 2011 at 9:10

GoogleCodeExporter commented 9 years ago 
Could it be that you created a regression with your first patch? You deleted a 
socket.listen(1) and now I get 

[  ERROR] [     net.py  418] failed to set up bluetooth server (must have 
already called socket.listen())

grettings

Original comment by jbuec...@gmail.com on 29 Aug 2011 at 10:03

GoogleCodeExporter commented 9 years ago 
This issue was updated by revision 152d10ba9749.

Original comment by obensonne@googlemail.com on 30 Aug 2011 at 3:13

GoogleCodeExporter commented 9 years ago 
Indeed, during my quick and dirty bug-fixing I removed that line. Should be 
fixed now.

Original comment by obensonne@googlemail.com on 30 Aug 2011 at 3:32

GoogleCodeExporter commented 9 years ago 
Concerning the exception handling, I'm not quite sure how to do it best. A 
reason why the server should not fail is that notebooks might have external 
Bluetooth dongles which are not plugged all the time, while Remuco should run 
nevertheless (to still provide Wifi for instance).

Original comment by obensonne@googlemail.com on 30 Aug 2011 at 3:58

GoogleCodeExporter commented 9 years ago 
Ok, the wifi thing is a good point. May a console output after starting like 
"bluetooth not availabe" or "bluetooth server couldn't start" and "wifi server 
started" or something like this?

Original comment by jbuec...@gmail.com on 31 Aug 2011 at 5:51

GoogleCodeExporter commented 9 years ago 
This issue was updated by revision 0492595121a2.

Errors are always logged to standard out now (in addition to the log
file).

Original comment by obensonne@googlemail.com on 31 Aug 2011 at 7:42

GoogleCodeExporter commented 9 years ago 
Do you accept this as a fix?

Original comment by obensonne@googlemail.com on 31 Aug 2011 at 7:43

GoogleCodeExporter commented 9 years ago 
For me, this fix is fine. This bug can be closed

Original comment by jbuec...@gmail.com on 31 Aug 2011 at 9:17

GoogleCodeExporter commented 9 years ago 
But I noticed one thing: If I do a normal diconnect with the client, the server 
says

ERROR: connection to client ('XX:...:XX', 8) broken (check the log for details)

I not await something like this with a clean disconnect. New bug?

Original comment by jbuec...@gmail.com on 31 Aug 2011 at 9:43

GoogleCodeExporter commented 9 years ago 
This issue was updated by revision 8d3a97edb7fa.

Client disconnects aren't handled as errors but warnings now.

Original comment by obensonne@googlemail.com on 31 Aug 2011 at 9:53

GoogleCodeExporter commented 9 years ago 
Thanks for reporting and testing.

Original comment by obensonne@googlemail.com on 31 Aug 2011 at 9:54

GoogleCodeExporter commented 9 years ago 
Wondering if it is possible to differenciate between a clean disconnect and a 
lost / broken connection?

But very good work!!!

Original comment by jbuec...@gmail.com on 31 Aug 2011 at 10:03

GoogleCodeExporter commented 9 years ago 
Not really. Remuco uses the Python GLib bindings 
(http://developer.gnome.org/pygobject/stable/glib-functions.html#function-glib--
io-add-watch) which do not provide this information. There's a hang-up event 
which Remuco looks for, but I've never seen it in the wild (instead there's 
always an error event -- if the client disconnects and when there is a real 
error).

Original comment by obensonne@googlemail.com on 31 Aug 2011 at 10:26