dbus exception when running channel scan

Bug #540937 reported by Frédéric Crozat on 2010-03-18
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
GNOME DVB Daemon
Undecided
Unassigned
gst-plugins-bad
Fix Released
Medium

Bug Description

when starting a scan, after selecting country and region, gnome-dvb-setup output several exception on the console (it might be related to the name of channels, which are known to contain non-ASCII characters in France) :

ERROR:dbus.connection:Exception in handler for D-Bus signal:
Traceback (most recent call last):
  File "/usr/lib/python2.6/site-packages/dbus/connection.py", line 214, in maybe_handle_message
    self._handler(*args, **kwargs)
  File "/usr/lib/python2.6/site-packages/gnomedvb/DBusWrapper.py", line 297, in on_channel_added
    self.emit("channel-added", freq, sid, name, network, channeltype, scrambled)
TypeError: could not convert type dbus.UInt32 to (null) required for parameter 0

this is with gnome-dvb-daemon 0.1.16 but it was already present in earlier releases

Related branches

Sebastian Pölsterl (sebp) wrote :

Parameter 0 is the channel's frequency, a uint. It's weird that it tries to convert the value to (null).

Frédéric Crozat (fcrozat) wrote :
Download full text (6.4 KiB)

Hmm, I ran gnome-dvb-daemon in debug mode and I got failure (not handled by UI). It works if I use dvbscan with the same dvb-t file for Paris.

log :

** (gnome-dvb-daemon:13186): DEBUG: Main.vala:128: Has dvbsrc >= 0.10.13: true
** (gnome-dvb-daemon:13186): DEBUG: Main.vala:128: Has dvbbasebin >= 0.10.13: true
** (gnome-dvb-daemon:13186): DEBUG: Main.vala:128: Has mpegtsparse >= 0.10.13: true
** (gnome-dvb-daemon:13186): DEBUG: Main.vala:128: Has rtpmp2tpay >= 0.10.14: true
** Message: Main.vala:55: Creating new Manager D-Bus service
** Message: Main.vala:193: Restoring device groups
** Message: Main.vala:76: Creating new RecordingsStore D-Bus service
** Message: Server.vala:26: Starting RTSP server
** Message: listening on port 8554
** Message: Services.vala:293: Creating new Rygel MediaServer D-Bus service
** (gnome-dvb-daemon:13186): DEBUG: Manager.vala:174: Created new Scanner D-Bus service for adapter 0, frontend 0 (org.gnome.DVB.Scanner.Terrestrial)
** (gnome-dvb-daemon:13186): DEBUG: TerrestrialScanner.vala:95: Reading scanning data from /usr/share/dvb/dvb-t/fr-Paris
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 474166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 498166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 522166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 538166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 562166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 586166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 714166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 738166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 754166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 762166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 786166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:308: Queueing new frequency 810166000
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:321: Received all tables: false (pat: false, sdt: false, nit: false, pmt: false)
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:360: Starting scanning frequency 474166000 (11 left)
** (gnome-dvb-daemon:13186): DEBUG: TerrestrialScanner.vala:153: Setting up pipeline for DVB-T scan
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:321: Received all tables: false (pat: false, sdt: false, nit: false, pmt: false)
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:360: Starting scanning frequency 498166000 (10 left)
** (gnome-dvb-daemon:13186): DEBUG: TerrestrialScanner.vala:153: Setting up pipeline for DVB-T scan
** (gnome-dvb-daemon:13186): DEBUG: Scanner.vala:433: Got lock

** (gnome-dvb-daemon:13186): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:13186): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:13186): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:13186): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:13186): WARNING **: S...

Read more...

Sebastian Pölsterl (sebp) wrote :

The last critical is caused if an error is posted on the bus and it tries to dispose the pipeline while it's still running. However, it's not clear what caused the error in the first place. Could you run the daemon in gdb with G_DEBUG=fatal-criticals and post the stacktrace, please.

Frédéric Crozat (fcrozat) wrote :
Download full text (8.6 KiB)

backstrace :

Starting program: /usr/bin/gnome-dvb-daemon
[Thread debugging using libthread_db enabled]
** Message: Main.vala:55: Creating new Manager D-Bus service
** Message: Main.vala:193: Restoring device groups
** Message: Main.vala:76: Creating new RecordingsStore D-Bus service
** Message: Server.vala:26: Starting RTSP server
** Message: listening on port 8554
** Message: Services.vala:293: Creating new Rygel MediaServer D-Bus service
[New Thread 0xb76afb70 (LWP 22935)]
[New Thread 0xb6c82b70 (LWP 22957)]

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** (gnome-dvb-daemon:22912): WARNING **: Scanner.vala:443: Read failure

** CRITICAL **: Scanner.vala:698: Erreur interne de flux de données. gstbasesrc.c(2507): gst_base_src_loop (): /GstPipeline:pipeline0/GstDvbSrc:dvbsrc:
streaming task paused, reason error (-5)
aborting...

Program received signal SIGTRAP, Trace/breakpoint trap.
IA__g_logv (log_domain=<value optimized out>, log_level=G_LOG_LEVEL_CRITICAL,
    format=0x80fc1c5 "Scanner.vala:698: %s %s",
    args1=0xbfffed8c "À*&\b¨æ&\bÿÿÿÿ\001") at gmessages.c:555
555 g_private_set (g_log_depth, GUINT_TO_POINTER (depth));
(gdb) thread apply all bt

Thread 3 (Thread 0xb6c82b70 (LWP 22957)):
#0 0xb7ff9713 in strcmp (p1=0xb7ba2a7f "g_static_rec_mutex_unlock_full",
    p2=0xb7ccc7a4 "g_static_rec_mutex_unlock_full") at strcmp.c:41
#1 0xb7febdbc in check_match (sym=0xb7b9d63c) at dl-lookup.c:150
#2 0xb7fec484 in do_lookup_x (new_hash=<value optimized out>,
    old_hash=0xb6c821f4, ref=0xb7cbfa08, result=0xb6c821e8, scope=0xb7fffa64,
    i=11, flags=5, skip=0x0, undef_map=0xb7e5b850) at dl-lookup.c:250
#3 0xb7fec6e8 in _dl_lookup_symbol_x (undef_name=<value optimized out>,
    undef_map=<value optimized out>, ref=0xb6c82230, symbol_scope=0xb7e5ba08,
    version=0x0, type_class=1, flags=5, skip_map=0x0) at dl-lookup.c:721
#4 0xb7ff0be5 in _dl_fixup (l=<value optimized out>,
    reloc_arg=<value optimized out>) at dl-runtime.c:118
#5 0xb7ff68d0 in _dl_runtime_resolve () at ../sysdeps/i386/dl-trampoline.S:37
#6 0xb7d3da08 in gst_task_func (task=0xb6d03810) at gsttask.c:221
#7 0xb7d3efe8 in default_func (tdata=0xb6d00db8, pool=0x811ac10)
    at gsttaskpool.c:70
#8 0xb7bfbfbf in g_thread_pool_thread_proxy (data=0x811b010)
    at gthreadpool.c:315
#9 0xb7bf9f64 in g_thread_create_proxy (data=0xb6d04088) at gthread.c:1893
#10 0xb7b82ae5 in start_thread () from /lib/i686/libpthread.so.0
#11 0xb7b0300e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:13...

Read more...

Sebastian Pölsterl (sebp) wrote :

Could please check if the attached patch helps.

Frédéric Crozat (fcrozat) wrote :

it is a little better (scan finishes) but it doesn't find any station :(

Sebastian Pölsterl (sebp) wrote :

You have attached the wrong file ;)

Frédéric Crozat (fcrozat) wrote :

oops, right file attached

Sebastian Pölsterl (sebp) wrote :

The debug log shows "Channel added", therefore you should see at least 5 channels. Have you checked if gnome-dvb-setup shows any errors?

That fact that some channels (but not all) are missing might be related to a bug in GStreamer which I already have a patch for and it's waiting to be committed.

The warning at the end is weird, could you get a trace with G_DEBUG=fatal-warnings for that one, please.

Frédéric Crozat (fcrozat) wrote :
Download full text (3.9 KiB)

do you have a bug number for gstreamer issue ? I could test the patch.

gnome-dvb-setup is showing the exception from comment #0 (on self.emit ("channel-added")) and also exception on "self.emit("frequency-scanned")).

backtrace for the last warning :

GLib-GObject-WARNING **: value "-10" of type `gint' is invalid or out of range for property `frequency' of type `gint'
aborting...

Program received signal SIGABRT, Aborted.
[Switching to Thread 0xb76b6b70 (LWP 13622)]
0xffffe424 in __kernel_vsyscall ()
(gdb) thread apply all bt

Thread 2 (Thread 0xb76b6b70 (LWP 13622)):
#0 0xffffe424 in __kernel_vsyscall ()
#1 0xb7a5ba81 in raise (sig=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#2 0xb7a5d3d2 in abort () at abort.c:92
#3 0xb7be067c in IA__g_logv (log_domain=<value optimized out>,
    log_level=G_LOG_LEVEL_WARNING,
    format=0xb7cb0f00 "value \"%s\" of type `%s' is invalid or out of range for property `%s' of type `%s'",
    args1=0xb76b5ffc "\030\033ж\rnË·Pâ\031\b\rnË·à\036Ê·\rnË·\030\033ж¸`k·0J0¶h\003Ì·d\003Ì·ø¤&\b\004") at gmessages.c:549
#4 0xb7be06a7 in IA__g_log (log_domain=0xb7caf984 "GLib-GObject",
    log_level=G_LOG_LEVEL_WARNING,
    format=0xb7cb0f00 "value \"%s\" of type `%s' is invalid or out of range for property `%s' of type `%s'") at gmessages.c:569
#5 0xb7c8c01d in object_set_property (nqueue=<value optimized out>,
    value=<value optimized out>, pspec=<value optimized out>,
    object=<value optimized out>) at gobject.c:964
#6 IA__g_object_set_valist (nqueue=<value optimized out>,
    value=<value optimized out>, pspec=<value optimized out>,
    object=<value optimized out>) at gobject.c:1488
#7 0xb7c8c1c8 in IA__g_object_set (_object=0x826a4f0,
    first_property_name=0x80e7a91 "frequency") at gobject.c:1594
#8 0x080d5a39 in dvb_scanner_set_uint_property (src=0x826a4f0,
    params=0xb631f660, key=0x80e7a91 "frequency") at src/Scanner.c:923
#9 0x0806989f in dvb_terrestrial_scanner_real_prepare (base=0x8270018)
    at src/Terrestrial/TerrestrialScanner.c:2516
#10 0x080d6e04 in dvb_scanner_start_scan (self=0x8270018) at src/Scanner.c:791
#11 0xb7bd3d00 in g_idle_dispatch (source=0xb6d01b38, callback=0,
    user_data=0x8270018) at gmain.c:4065
#12 0xb7bd5c8e in g_main_dispatch (context=<value optimized out>)
    at gmain.c:1960
#13 IA__g_main_context_dispatch (context=<value optimized out>) at gmain.c:2513
#14 0xb7bd99c8 in g_main_context_iterate (context=0x81a0200,
    block=<value optimized out>, dispatch=1, self=0x819f1d8) at gmain.c:2591
#15 0xb7bd9ed7 in IA__g_main_loop_run (loop=0x8122b08) at gmain.c:2799
#16 0x080d79b9 in dvb_scanner_worker (self=<value optimized out>)
    at src/Scanner.c:621
#17 _dvb_scanner_worker_gthread_func (self=<value optimized out>)
    at src/Scanner.c:297
#18 0xb7c00c14 in g_thread_create_proxy (data=0x819f1d8) at gthread.c:1893
#19 0xb7b89ae5 in start_thread () from /lib/i686/libpthread.so.0
#20 0xb7b0a00e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

Thread 1 (Thread 0xb77fe6c0 (LWP 13607)):
#0 0xffffe424 in __kernel_vsyscall ()
---Type <return> to continue, or q <return> to quit---
#1 0xb7afeb16 in __poll (fds=0xb7b7fff4, nfds=4, timeout=1951)
...

Read more...

Sebastian Pölsterl (sebp) wrote :

My patch is available at https://bugzilla.gnome.org/show_bug.cgi?id=614479

There seems to be some kind of problem with signed and unsigend ints. The property setter of dvbsrc expects an int whereas it should except uint, which is used internally anyway (see https://bugzilla.gnome.org/show_bug.cgi?id=614475). Something similar seems to happen when the signals are emitted.

That means we have to dig deeper: What architecture are you running and which version of Vala do you use?

Sebastian Pölsterl (sebp) wrote :

It would be great if you could upload a short recording (10-20s are enough) somewhere so I can check if something went wrong in GStreamer. You can create a proper channels.conf with dvb-app's scan and the file /usr/share/dvb/dvb-t/fr-Paris. If you start gnome-dvb-control and go to preferences you can manually add a device specify the channels.conf from scan.

Frédéric Crozat (fcrozat) wrote :

architecture : x86
vala used : 0.7.10 (vala 0.8.0 landed on cooker since but I didn't test yet)

I'll try to do some test with your patches on gstreamer later.

It appears fr-Paris might not be right because dvb-app scan didn't find all available channels, unlike a full scan.

I did a recording for 1min, available at http://dl.free.fr/vyrz7yo4B with the "partial" scan file.

Sebastian Pölsterl (sebp) wrote :

I had a closer look at the file you provided. GStreamer retrieves the correct information, the file claims a frequency of 0xffff which then causes the uint/int issue. Obviously, such frequency doesn't make sense. Dies dvb-apps scan find no channels at all or are just some missing, in the latter case I should take a closer look how they deal with this situation.

Frédéric Crozat (fcrozat) wrote :

dvb-apps scan finds "some" channels, but not all of them (I can attach both channels.conf file, if you are interested)

Sebastian Pölsterl (sebp) wrote :

The GStreamer bugs are now fixed in their git version.

Regarding the wrong/missing channels issue bug #548738 already covers that, please discuss this issue there.

Changed in gnome-dvb-daemon:
status: New → Fix Committed
Frédéric Crozat (fcrozat) wrote :

ok, I can confirm the dbus exceptions are gone with the gstreamer fixes, but I don't have any channel found during a scan and I now have "warning: error tuning channel: invalid argument".

I'll switch to bug #548738 for the channel not found (btw, you should use different names for patches, calling all of them scanner.patch is not a good idea ;)

Frédéric Crozat (fcrozat) wrote :

oops, my bad, I just saw one single dbus exception at the end of the scan (no channel was found) :

  self.emit("frequency-scanned", freq, freq_left)
TypeError: could not convert type dbus.UInt32 to (null) required for parameter 0

Sebastian Pölsterl (sebp) wrote :

Where does the message "warning: error tuning channel: invalid argument" appear, could you post debug log, please?

I suppose the dbus exception is caused by the value being to big for uint32. This should disappear with the patch from bug #548738, because tuning data contained in the transport stream is no longer used (sorry about the confusion with the patch names).

Frédéric Crozat (fcrozat) wrote :
Frédéric Crozat (fcrozat) wrote :

and from kernel log :

DVB: adapter 0 frontend 0 frequency 4294967286 out of range (45000000..860000000)

is output when invalid argument is returned.

Changed in gnome-dvb-daemon:
status: Fix Committed → Fix Released
Changed in gst-plugins-bad:
status: Unknown → Fix Released
Changed in gst-plugins-bad:
importance: Unknown → Medium
Changed in gst-plugins-bad:
status: Fix Released → Confirmed
Changed in gst-plugins-bad:
status: Confirmed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.