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:
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
~ # /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 (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?
@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
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...
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.
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
Hi Marten,
your patch should go to cvs?
Bye,
Walter
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
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
thumbs up from me as well!
funny how a (potential) bug can be dormant for so
long, and then just kick in.
Marten's patch is now in the git repo, just fyi.
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
There's a few more things I want to do first, but yes. I can't consider a time scale yet though.