liblttng-ust0 Error opening shm /lttng-ust-wait-5 - do not link liblttng-ust!

[Michael Zanetti]

Confined apps don't have access to this and continuously produce this error message in stderr:

libust[31283/31285]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)

This is printed to the application's log about once every other second and makes it hard to read the application's own debug output. For a better app developer experience this message should be silenced.

[Thomas Voß (thomas-voss)]

UST is doing the right thing here. The error arises as access to the shared memory segment is mediated by AppArmor. For that, we should strip all lttng tracepoints from production builds for QtUbuntu and the Platform API.

[Ted Gould (ted)]

What I did for UAL is turn them on with an environment variable. That way we can still test the production images but we don't have to get errors with confined apps.

[Dubstar_04 (dubstar-04)]

I am getting this error when trying to play a video. Is this likely to be fixed soon?

[Franck (alci)]

This also happen with libvirtd apparmor profile in enforce mode: virtual machines (ie sub profiles with libvirt-someUUID) will constantly complain they are denied read access to /dev/shm/lttng-ust-wait-5

[dinamic (dinamic6661)]

i'm getting this when trying to load an image with sdl2_image o_O

[dinamic (dinamic6661)]

SDL_Init()
shm_open() failed: Permission denied
Initialized, drawing...
libust[13945/13949]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[13945/13949]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[13945/13948]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)

[Jean-Baptiste Lallement (jibel)]

Raising importance to high, it has a severe impact on the developer experience by making logs very difficult to read.

[David Barth (dbarth)]

Adding webapp-container, which is impacted. We can implement Ted's suggestion of turning on tracepoints on demand on our side.

[Michi Henning (michihenning)]

These message are also all through the log for the camera app.

[Jim Hodapp (jhodapp)]

Making it difficult to debug qtubuntu-media with music-app. Would like to see this fixed very soon.

[Jamie Strandboge (jdstrand)]

Pat, it should be a simple fix to disable the log line, but no one is currently assigned (I removed Ricardo from the assignment just now).

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Gerry Boland (gerboland)]

I don't think it is the application printing this message. Attaching to it with strace, it's not printing out when these lines appear in the log. Upstart is reading these lines from *somewhere*, and writing them to the log fine. But no idea from where yet

[Pat McGowan (pat-mcgowan)]

@gerry aiui we need to just do what ted said he did for ual in comment #2

[Gerry Boland (gerboland)]

@pat we need more of Ted's input then, as I don't follow what he's suggesting as a fix.

My understanding is that lttng reporting is only enabled with a particular env var. So it should always be off by default. But these errors printing in logs would suggest otherwise.

[Pat McGowan (pat-mcgowan)]

@gerry for ual thats the case but not for the other packages that are causing these to be logged. The same fix in ual needs to be applied to use an env var and macro in qtmir and maybe elsewhere,

look at ual-tracepoints.h in ubuntu-app-launch

[Gerry Boland (gerboland)]

/me has to retract comment #13, it is indeed the app printing the message. Camera app has 2 threads printing it

sudo strace -f -e write -p `pidof camera-app` 2>&1 | grep ust
[pid 14107] write(2, "libust[14085/14107]: Error: Erro"..., 114 <unfinished ...>
[pid 14106] write(2, "libust[14085/14106]: Error: Erro"..., 108) = 108

and looking at the threads involved:

(gdb) i thre
  Id Target Id Frame
  20 Thread 0xb2f67410 (LWP 14097) "RPC Thread" 0xb64ca4e2 in poll () at ../sysdeps/unix/syscall-template.S:81
  19 Thread 0xb23e1410 (LWP 14099) "arch_worker" 0xb46ab840 in ?? ()
  18 Thread 0xb2442b40 (LWP 14100) "camera-app" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:47
  17 Thread 0xb19ff410 (LWP 14101) "SWD-GPU Job" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  16 Thread 0xb11ff410 (LWP 14102) "SWD-Frame" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  15 Thread 0xb07bb410 (LWP 14104) "QQmlThread" 0xb64ca4e2 in poll () at ../sysdeps/unix/syscall-template.S:81
  14 Thread 0xae6b2410 (LWP 14106) "QQmlThread" 0xb64ae4e2 in nanosleep () at ../sysdeps/unix/syscall-template.S:81
  13 Thread 0xadeb2410 (LWP 14107) "QQmlThread" 0xb64ae4e2 in nanosleep () at ../sysdeps/unix/syscall-template.S:81
  12 Thread 0xad0ff410 (LWP 14110) "gdbus" 0xb64ca4e2 in poll () at ../sysdeps/unix/syscall-template.S:81
  11 Thread 0xab97a410 (LWP 14112) "camera-app" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  10 Thread 0xa9faa410 (LWP 14117) "QQuickPixmapRea" 0xb64ca4e2 in poll () at ../sysdeps/unix/syscall-template.S:81
  9 Thread 0xa9223410 (LWP 14118) "Input dispatch" 0xb64ca4e2 in poll () at ../sysdeps/unix/syscall-template.S:81
  8 Thread 0xa83ff410 (LWP 14124) "camera-app" 0xb64d1132 in epoll_wait () at ../sysdeps/unix/syscall-template.S:81
  7 Thread 0xa7bff410 (LWP 14126) "QSGRenderThread" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  6 Thread 0xa73ff410 (LWP 14127) "Swap Worker" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  5 Thread 0xa63ff410 (LWP 14128) "camera-app" 0xb46ac9f4 in ?? ()
  4 Thread 0xa5bff410 (LWP 14140) "Binder_1" 0xb46ab840 in ?? ()
  3 Thread 0xa53ff410 (LWP 14141) "Binder_2" 0xb46ab840 in ?? ()
  2 Thread 0xa4bff410 (LWP 14172) "Binder_3" 0xb46ab840 in ?? ()
* 1 Thread 0xb6f32000 (LWP 14085) "camera-app" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
(gdb) t 14
[Switching to thread 14 (Thread 0xae6b2410 (LWP 14106))]
#0 0xb64ae4e2 in nanosleep () at ../sysdeps/unix/syscall-template.S:81
81 ../sysdeps/unix/syscall-template.S: No such file or directory.
(gdb) bt
#0 0xffffffff in nanosleep () at ../sysdeps/unix/syscall-template.S:81
#1 0xffffffff in __sleep (seconds=0) at ../sysdeps/unix/sysv/linux/sleep.c:138
#2 0xffffffff in () at /usr/lib/arm-linux-gnueabihf/liblttng-ust.so.0
(gdb) t 13
[Switching to thread 13 (Thread 0xadeb2410 (LWP 14107))]
#0 0xb64ae4e2 in nanosleep () at ../sysdeps/unix/syscall-template.S:81
81 in ../sysdeps/unix/syscall-template.S
(gdb) bt
#0 ...

[Michael Zanetti (mzanetti)]

Trying to debug some telegram issues, here's what a log to work with looks like.

Bump! :)

[Gerry Boland (gerboland)]

Playing around with the camera app, I found that if I removed the "Ubuntu.Content" plugin, the LTTng message stopped. So suspect something content hub is linking with

[Gerry Boland (gerboland)]

Yep, as test, inside /usr/share/click/preinstalled/com.ubuntu.camera/current create this simple QML file: test.qml:

import QtQuick 2.0
import Ubuntu.Content 0.1

Rectangle {
    color: "red"
}

and execute with:

aa-exec-click -p com.ubuntu.camera_camera_3.0.0.611 -- qmlscene test.qml --desktop_file_hint=dialer-app

You'll get the LTTng messages printed

[Gerry Boland (gerboland)]

===========test2.qml================
import QtQuick 2.3
import Ubuntu.Content 0.1

Rectangle { color: "pink" }

===========test.qml==============
import QtQuick 2.0

Rectangle {
    color: "red"
    Loader { id: loader; anchors.fill: parent; }
    MouseArea {
        anchors.fill: parent
        onClicked: loader.source = "test2.qml"
    }
}

Run:

LTTNG_UST_DEBUG=1 aa-exec-click -p com.ubuntu.camera_camera_3.0.0.611 -- qmlscene test.qml --desktop_file_hint=dialer-app

which enables extra LTTng output. I get some from Mir at startup - still no LTTng warning messages printing. But then I hit the screen, to load Ubuntu.Content plugin. I then get messages that ubuntu-app-launch registers tracepoints, and the warning messages start repeating.

My log here: http://pastebin.ubuntu.com/14883688/

Maybe UAL imported as library is doing it? I don't know yet

[pramathesh ambasta (pramathesh-ambasta)]

Experience a similar error when testing my app recorder.

I am trying to add a "share" ability via the content-hub. I get to the point when the peer picker window is displayed after which there is a failed event.

On checking my app logs I find:

libust[24601/24606]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[18402/18405]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[18402/18405]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[18402/18406]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[18402/18406]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[20659/20663]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[20659/20663]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[20659/20662]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[20659/20662]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[9690/9694]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[9690/9694]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[9690/9693]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[9690/9693]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[14795/14798]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[14795/14798]: Error: Error opening shm /lttng-ust-wait-5 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[14795/14799]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)
libust[14795/14799]: Error: Error opening shm /lttng-ust-wait-5-32011 (in get_wait_shm() at lttng-ust-comm.c:958)

[Josué (j2g2rp)]

I don't know if it's normal to have more than 70 files named: untrusted-helper-push-helper:xxxxxxx:com.ubuntu.telegram_push_2.0.4.0 in upstart folder which have four lines of these error inside :/

[Gerry Boland (gerboland)]

Ok, I have an idea. content-hub links to libubuntu-app-launch.so, which links to liblttng-ust.so. On load of liblttng-ust.so, it registers 2 tracepoint providers by default: ust_baddr_statedump and lttng_ust_tracef. These are causing our repeating error messages.

Instead, I think we need to refactor UAL to dynamically load liblttng-ust.so, instead of linking to it, and dlload it when tracing is desired. See the strangely-named "Dynamic linking" section of the doc:
http://www.lttng.org/docs/#doc-building-tracepoint-providers-and-user-application

This is what Mir is doing, and works well there. See
http://bazaar.launchpad.net/~mir-team/mir/development-branch/view/head:/src/common/report/lttng/tracepoint_provider.cpp

[Ted Gould (ted)]

So did some investigation into this and why the error message is printing. It seems like it shouldn't be. Then I realized I was looking at the version of libttng-ust in Xenial and not the one in Vivid. This is fixed in Xenial with ust 2.7 in that it'll only print the errors if UST debugging is turned on. Which is the behavior that everyone wants.

We could work around it in UAL, but I think that if we want the fix for Vivid it would be best to upload the new version of ust to the overlay PPA or to wait until we move the phones to Vivid.

[Gerry Boland (gerboland)]

Newer version of LTTng landed

[Olivier Tilloy (osomon)]

It seems webbrowser-app is affected by this issue again (see bug #1606946).