vomp Server: RRProc - threadMethod err 1

[Zimbo]

Hi,

I've got a problem with my MVP. After starting and loading the dongle the MVP stops with the message "Connecting to vdr". The vomp log says:

Code Select Expand


21:55:01.184245 [debug]  BOOTPD - Wait finished
21:55:01.184372 [debug]  BOOTPD - Got request
21:55:01.184527 [debug]  Config - Opened config file: /var/lib/vdr/plugins/vompserver/vomp-00-xx-xx-xx-xx-xx.conf
21:55:01.184565 [debug]  BOOTPD - Opened config file: /var/lib/vdr/plugins/vompserver/vomp-00-xx-xx-xx-xx-xx.conf
21:55:01.208176 [debug]  Config - Config error: Key IP not found
21:55:01.208258 [WARN]   BOOTPD - No IP found for MVP. Hopefully it has one already...
21:55:01.208401 [debug]  Config - Config error: Key Override IP not found
21:55:01.208439 [debug]  BOOTPD - Will not change MVP IP if it already has one
21:55:01.208469 [debug]  BOOTPD - Leave YI=0 as MVP already has good IP
21:55:01.208731 [debug]  BOOTPD - Starting wait
21:55:01.339426 [debug]  Tftpd - Wait finished
21:55:01.339566 [debug]  TftpClient - Client handler started
21:55:01.339714 [debug]  Tftpd - Starting wait
21:55:01.339891 [debug]  TftpClient - RRQ received for vomp-dongle
21:55:01.339984 [info]   TftpClient - File: '/usr/share/vdr-plugin-vompserver/vomp-dongle'
21:55:08.499499 [info]   TftpClient - File transfer finished
21:55:08.499686 [info]   TftpClient - processMessage terminating connection
21:55:40.472471 [debug]  UDPReplier - UDP request from 192.168.xx.xx
21:55:42.024889 [debug]  Client - Config dir: /var/lib/vdr/plugins/vompserver
21:55:42.025006 [debug]  MediaPlayer::registerMediaProvider - p=0x93c45670
21:55:42.025087 [debug]  MediaLauncher - init
21:55:42.049626 [debug]  Config - Config error: Key Command.Name.1 not found
21:55:42.049825 [debug]  Config - Config error: Key Command.Name.2 not found
21:55:42.049951 [debug]  Config - Config error: Key Command.Name.3 not found
21:55:42.050109 [debug]  Config - Config error: Key Command.Name.4 not found
21:55:42.050257 [debug]  Config - Config error: Key Command.Name.5 not found
21:55:42.050429 [debug]  Config - Config error: Key Command.Name.6 not found
21:55:42.050548 [debug]  Config - Config error: Key Command.Name.7 not found
21:55:42.050666 [debug]  Config - Config error: Key Command.Name.8 not found
21:55:42.050783 [debug]  Config - Config error: Key Command.Name.9 not found
21:55:42.050901 [debug]  Config - Config error: Key Command.Name.10 not found
21:55:42.051018 [debug]  Config - Config error: Key Command.Name.11 not found
21:55:42.051172 [debug]  Config - Config error: Key Command.Name.12 not found
21:55:42.051310 [debug]  Config - Config error: Key Command.Name.13 not found
21:55:42.051430 [debug]  Config - Config error: Key Command.Name.14 not found
21:55:42.051601 [debug]  Config - Config error: Key Command.Name.15 not found
21:55:42.051719 [debug]  Config - Config error: Key Command.Name.16 not found
21:55:42.051837 [debug]  Config - Config error: Key Command.Name.17 not found
21:55:42.051955 [debug]  Config - Config error: Key Command.Name.18 not found
21:55:42.052073 [debug]  Config - Config error: Key Command.Name.19 not found
21:55:42.052190 [debug]  Config - Config error: Key Command.Name.20 not found
21:55:42.052308 [debug]  Config - Config error: Key Command.Name.21 not found
21:55:42.052459 [debug]  Config - Config error: Key Command.Name.22 not found
21:55:42.053050 [debug]  Config - Config error: Key Command.Name.23 not found
21:55:42.053211 [debug]  Config - Config error: Key Command.Name.24 not found
21:55:42.053337 [debug]  Config - Config error: Key Command.Name.25 not found
21:55:42.053404 [debug]  Config - Config error: Key Command.Name.26 not found
21:55:42.053501 [debug]  Config - Config error: Key Command.Name.27 not found
21:55:42.053568 [debug]  Config - Config error: Key Command.Name.28 not found
21:55:42.053657 [debug]  Config - Config error: Key Command.Name.29 not found
21:55:42.053762 [debug]  Config - Config error: Key Command.Name.30 not found
21:55:42.053828 [debug]  Config - Config error: Key Command.Name.31 not found
21:55:42.053894 [debug]  Config - Config error: Key Command.Name.32 not found
21:55:42.053969 [debug]  Config - Config error: Key Command.Name.33 not found
21:55:42.054035 [debug]  Config - Config error: Key Command.Name.34 not found
21:55:42.054101 [debug]  Config - Config error: Key Command.Name.35 not found
21:55:42.054167 [debug]  Config - Config error: Key Command.Name.36 not found
21:55:42.054233 [debug]  Config - Config error: Key Command.Name.37 not found
21:55:42.054299 [debug]  Config - Config error: Key Command.Name.38 not found
21:55:42.054365 [debug]  Config - Config error: Key Command.Name.39 not found
21:55:42.054431 [debug]  Config - Config error: Key Command.Name.40 not found
21:55:42.054498 [debug]  Config - Config error: Key Command.Name.41 not found
21:55:42.054564 [debug]  Config - Config error: Key Command.Name.42 not found
21:55:42.054630 [debug]  Config - Config error: Key Command.Name.43 not found
21:55:42.054696 [debug]  Config - Config error: Key Command.Name.44 not found
21:55:42.054792 [debug]  Config - Config error: Key Command.Name.45 not found
21:55:42.054859 [debug]  Config - Config error: Key Command.Name.46 not found
21:55:42.054926 [debug]  Config - Config error: Key Command.Name.47 not found
21:55:42.055043 [debug]  Config - Config error: Key Command.Name.48 not found
21:55:42.055273 [debug]  Config - Config error: Key Command.Name.49 not found
21:55:42.055375 [debug]  Config - Config error: Key Command.Name.50 not found
21:55:42.055415 [debug]  MediaLauncher - found 0 commands
21:55:42.055495 [debug]  Client - VompClient run success
21:55:42.055549 [debug]  Client - Waiting
21:55:42.055618 [debug]  Client - Received chan=1, ser=1, op=1, edl=6
21:55:42.055651 [debug]  RRProc - recvReq set req and signalled
21:55:42.055679 [debug]  Client - Waiting
21:55:42.055716 [debug]  RRProc - threadMethod startup
21:55:42.055746 [ERR]    RRProc - threadMethod err 1



and the mvp debug output says

Code Select Expand

~ # /vompclient -d
00:10:56.110633 [info]   39 Core - Starting up...
00:10:56.111432 [info]   39 Core - Signal handlers set up successfully
00:10:56.111768 [info]   39 Core - Remote module initialised
00:10:56.111997 [info]   39 Core - LED module initialised
00:10:56.112865 [debug]  39 MTD - Located MTD device: /dev/mtd1
00:10:56.118030 [info]   39 Core - Mtd module initialised
00:10:56.119725 [info]   39 Core - Timers module initialised
00:10:56.119994 [info]   39 Core - Read from MTD: PAL 720x576
00:10:56.550122 [debug]  39 Video - Setting aspect to 0
00:10:56.560077 [debug]  39 Video - Setting aspect to 0
00:10:57.040080 [debug]  39 Video - Setting aspect to 0
00:10:57.041322 [info]   39 Core - Video module initialised
00:10:57.129105 [info]   39 Core - OSD module initialised
00:10:57.137775 [debug]  39 Audio - MUTE OFF OFF OFF
00:10:57.138323 [info]   39 Core - Audio module initialised
00:10:57.138792 [info]   39 Core - VDR module initialised
00:10:57.139246 [info]   39 Core - BoxStack module initialised
00:10:57.139933 [info]   39 Core - Command module initialised
00:10:57.140450 [notice] 39 Core - Startup successful
00:10:57.141003 [debug]  39 Boxx - Construct, now 1
00:10:57.270309 [debug]  39 BoxStack - add called
00:10:57.270856 [debug]  39 BoxStack - Locked for add
00:10:57.271301 [debug]  39 BoxStack - Unlocked for add
00:10:57.271742 [debug]  39 BoxStack - Update called
00:10:57.272182 [debug]  39 BoxStack - Locked for update
00:10:57.378255 [debug]  39 BoxStack - Unlocked for update
00:10:57.378741 [debug]  39 BoxStack - Locked for remove
00:10:57.379218 [debug]  39 BoxStack - Unlocked for remove
00:10:57.379665 [debug]  39 BoxStack - remove: going to delete boxx 0x1024cab0,
num 0
00:10:57.381056 [debug]  39 Boxx - Destruct, now 0
00:10:57.381586 [debug]  39 Boxx - Construct, now 1
00:10:57.447043 [debug]  39 Command - PAL wallpaper selected
00:10:57.447758 [debug]  39 BJpeg - draw Jpeg Started sfc=0x1024cbc8, rdr=0x1024
ccb0
00:10:57.449479 [debug]  39 BJpeg - JPEG read header w=720 h=576, rot=0
00:10:57.450996 [debug]  39 BJpeg - JPEG startup done pw=720 ph=576, xo=0,yo=0,
jw=720, jh=576, rot=0
00:10:57.515879 [debug]  39 BJpeg - start drawing
00:10:57.516370 [debug]  39 BJpeg - jpeg  draw scale 1 image: 720 576, picture:
720 576
00:10:58.154689 [debug]  39 BJpeg - Done all jpeg_read
00:10:58.155421 [debug]  39 BJpeg - cleanup src, src=0x1024cf78, buf=0x30266008
00:10:58.156004 [debug]  39 BJpeg - jpeg shutdown done
00:10:58.156474 [debug]  39 BJpeg - deleted buffer
00:10:58.156917 [debug]  39 BoxStack - add called
00:10:58.157363 [debug]  39 BoxStack - Locked for add
00:10:58.157806 [debug]  39 BoxStack - Unlocked for add
00:10:58.158250 [debug]  39 BoxStack - Update called
00:10:58.158691 [debug]  39 BoxStack - Locked for update
00:10:58.265572 [debug]  39 BoxStack - Unlocked for update
00:10:58.266119 [debug]  39 Boxx - Construct, now 2
00:10:58.266583 [debug]  39 Boxx - Construct, now 3
00:10:58.280693 [debug]  39 BoxStack - add called
00:10:58.281183 [debug]  39 BoxStack - Locked for add
00:10:58.281624 [debug]  39 BoxStack - Unlocked for add
00:10:58.282518 [debug]  42 TBBoxx - Draw
00:10:58.298496 [debug]  42 VConnect - Draw done
00:10:58.299097 [debug]  42 BoxStack - Update called
00:10:58.299569 [debug]  42 BoxStack - Locked for update
00:10:58.336776 [debug]  42 BoxStack - Unlocked for update
00:10:58.337288 [debug]  39 UDP - Starting UDP command server
00:10:58.338570 [debug]  39 UDP - UDP command server started
00:10:58.339462 [notice] 42 VDR - Broadcasting for server
00:10:59.840157 [notice] 42 VConnect - Connecting to server at 192.168.xxx.xxx
00:10:59.842830 [notice] 42 Wol - Found etheraddr 00:01:xx:xx:xx:xx
00:10:59.843365 [notice] 42 Wol - Server IP set
00:10:59.843884 [debug]  42 TBBoxx - Draw
00:10:59.859604 [debug]  42 VConnect - Draw done
00:10:59.860122 [debug]  42 BoxStack - Update called
00:10:59.860579 [debug]  42 BoxStack - Locked for update
00:10:59.897766 [debug]  42 BoxStack - Unlocked for update
00:10:59.899335 [debug]  44 VDR - VDR RUN
00:10:59.900073 [debug]  42 Command - Connected ok, doing login
00:10:59.901010 [debug]  42 VDR - RR sleep - opcode 1
00:11:07.890053 [debug]  44 VDR - Sending KA packet
00:11:07.891396 [debug]  44 VDR - Rxd correct KA reply
00:11:13.890055 [debug]  44 VDR - Sending KA packet
00:11:13.891440 [debug]  44 VDR - Rxd correct KA reply
00:11:19.890054 [debug]  44 VDR - Sending KA packet

MartenR advised me at the vdr portal to post the problem here because it might be a bug?!
http://www.vdr-portal.de/board/thread.php?postid=922630

I am running c't vdr 7 / eTobi updated to sid (Linux 2.6.32-5-686 SMP) on a a Pentium M / i855 Machine.
vdr version is 1.6.0-17ct
vompserver is 0.3.1-2
vompclient is 0.3.1-1

The combination had worked up to the last update.

Any Ideas on that?

[MartenR]

@Chris
I looked at the logs, and it seems that a VompClientRRProc got a request before it entered the threadMethod, which causes the threadMethod to exist.
Seems to me like bad timing, which so far did not occur for most users, so a potential bug.

Anyway, why is it not allowed to have a request in req_queue before entering the threadMethod, I do not understand hy it is handled this way?

Marten

[riban]

I have started to suffer from this since I updated my Ubuntu 10.04 LST-2 VDR server. After a little investigation, I concur with Marten that there is already a message in req_queue when VompClientRRProc::threadMethod() is called.

I have worked around this for now by moving  rrproc.init() to before media=new MediaPlayer() and mediaprovider=new ServerMediaFile(cfgBase,media) in vompclient.c.

I think the plugin was spending time dealing with the MediaPlayer and hence there was time for the message to be received before rrproc.init was called.

I agree with Marten that there is a bug with the order things are initialised. I may find time to investigate further...
 

[meinetwegen]

This is quite a common problem of vompserver 0.3.1. There already exists a patch for it. You can find it here:

http://www.russle.net/vomp/0.3.1/server/05_client_startup_fail

Unfortunately this project seems to be abandoned so that the patches do not make it into the CVS.

[MartenR]

Actually, I do not like this patch, because he is solving the thread locking in a dirty way.
You can use the attached patch, which I coded and which is used for the debian ctvdr paket since the problem occured.
The patch cares about thread synchronization opposed to the other patch.

Marten

[hondansx]

Hi Marten,

your patch should go to cvs?

Bye,
Walter

[MartenR]

I think so, I think I have send Chris the patch a long time ago, but may be it was lost, we had this before with my email address.

Marten

[stu-e]

Thanks for the patch
My Vomp setup has been suffering with this problem, intermittently for a very long time.
I applied the patch to the server and the problem has not occurred for a couple of weeks now.
I am confident the problem has been fixed for me.

Stu-e

[Harry]

thumbs up from me as well!

funny how a (potential) bug can be dormant for so
long, and then just kick in.

[Chris]

Marten's patch is now in the git repo, just fyi.

[riban]

Hi

Is there any chance this could be rolling in to a new release on the main web page?
My vdr blew up earlier and so I am building a new one and got caught out by this again. I vaguely remembered the issue so looked for and found this thread and applied the patch and now it works but it would have been less hassle / time if the current release had it already applied.

Cheers

Walt

[Chris]

There's a few more things I want to do first, but yes. I can't consider a time scale yet though.