Bug 461865 - pulseaudio complains about failure to import memory block/shm_open() failure
pulseaudio complains about failure to import memory block/shm_open() failure
Status: CLOSED WONTFIX
Product: Fedora
Classification: Fedora
Component: pulseaudio (Show other bugs)
10
All Linux
medium Severity medium
: ---
: ---
Assigned To: Lennart Poettering
Fedora Extras Quality Assurance
: Triaged
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-09-10 20:33 EDT by Tom London
Modified: 2009-12-18 01:22 EST (History)
2 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2009-12-18 01:22:57 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
/var/log/messages segment showing "shm.c: shm_open() failed: No such file or directory" (35.69 KB, text/plain)
2008-10-08 09:56 EDT, Tom London
no flags Details

  None (edit)
Description Tom London 2008-09-10 20:33:48 EDT
Description of problem:
See this every now and then in /var/log/messages:

Sep 10 17:23:31 tlondon pulseaudio[3177]: shm.c: shm_open() failed: No such file or directory
Sep 10 17:23:31 tlondon pulseaudio[3177]: pstream.c: Failed to import memory block.

Not sure it's a problem.....

Version-Release number of selected component (if applicable):
pulseaudio-0.9.12-4.fc10.i386

How reproducible:
Intermittant

Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:
Comment 1 Lennart Poettering 2008-09-11 08:42:51 EDT
Hmm, normally the SHM files of all clients should be accessible in /dev/shm. The output you are experiencing suggests that either that path got missing on your machine or the shm segs in it.

Is SELinux enabled?

Could you please set log-level=debug in /etc/pulse/default.pa and the logout and login again, and post a more complete excerpt from syslog when this happens?
Comment 2 Tom London 2008-09-11 09:24:49 EDT
SELinux is enabled, but these come out after pulse/rhythmbox has been running for hours.

Sorry, but what exactly is the format of the line to be added to default.pa (couldn't find anything close in the man pages or in http://pulseaudio.org/wiki/CLI?  Is it "set log-level=debug" or just "log-level=debug"?

A bit more on the scenario: I start rhythmbox pretty much immediately after I login to gnome, and it just plays and plays through a collection of mp3s that I have stored on a mounted ntfs-3g file system.  I occasionally stop/restart rhythmbox when someone comes into my office.
Comment 3 Tom London 2008-09-11 10:01:31 EDT
OK, I set 'log-level=debug' in /etc/pulse/daemon.conf and rebooted.

That right?
Comment 4 Tom London 2008-09-12 18:13:04 EDT
OK, got one.  Took almost 2 days....

As above, the setup is system up and running since about 9AM (now 3PM), with rhythmbox pretty much continuously running.  I did not notice any interruptions of rhythmbox.

I extracted from /var/log/messages the messages from about a 2 minute interval.  Let me know if you want the complete day's log (more than 500KB).

Sep 12 14:36:04 tlondon pulseaudio[4086]: client.c: Created 71 "Native client (UNIX socket client)"
Sep 12 14:36:04 tlondon pulseaudio[4086]: protocol-native.c: Got credentials: uid=500 gid=500 success=1
Sep 12 14:36:05 tlondon pulseaudio[4086]: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Pidgin.
Sep 12 14:36:05 tlondon pulseaudio[4086]: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Pidgin.
Sep 12 14:36:05 tlondon pulseaudio[4086]: resampler.c: Using resampler 'speex-float-3'
Sep 12 14:36:05 tlondon pulseaudio[4086]: resampler.c: Using float32le as working format.
Sep 12 14:36:05 tlondon pulseaudio[4086]: resampler.c: Choosing speex quality setting 3.
Sep 12 14:36:05 tlondon pulseaudio[4086]: sink-input.c: Created input 55 "Playback Stream" on alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right
Sep 12 14:36:05 tlondon pulseaudio[4086]: protocol-native.c: Requested tlength=199.55 ms, minreq=9.98 ms
Sep 12 14:36:05 tlondon pulseaudio[4086]: protocol-native.c: Final latency 379.14 ms = 179.59 ms + 2*9.98 ms + 179.59 ms
Sep 12 14:36:05 tlondon pulseaudio[4086]: sink-input.c: Freeing input 55 "Playback Stream"
Sep 12 14:36:05 tlondon pulseaudio[4086]: client.c: Freed 71 "Pidgin"
Sep 12 14:36:05 tlondon pulseaudio[4086]: protocol-native.c: Connection died.
Sep 12 14:36:14 tlondon pulseaudio[4086]: client.c: Created 72 "Native client (UNIX socket client)"
Sep 12 14:36:14 tlondon pulseaudio[4086]: protocol-native.c: Got credentials: uid=500 gid=500 success=1
Sep 12 14:36:14 tlondon pulseaudio[4086]: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Pidgin.
Sep 12 14:36:14 tlondon pulseaudio[4086]: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Pidgin.
Sep 12 14:36:14 tlondon pulseaudio[4086]: resampler.c: Using resampler 'speex-float-3'
Sep 12 14:36:14 tlondon pulseaudio[4086]: resampler.c: Using float32le as working format.
Sep 12 14:36:14 tlondon pulseaudio[4086]: resampler.c: Choosing speex quality setting 3.
Sep 12 14:36:14 tlondon pulseaudio[4086]: sink-input.c: Created input 56 "Playback Stream" on alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right
Sep 12 14:36:14 tlondon pulseaudio[4086]: protocol-native.c: Requested tlength=199.55 ms, minreq=9.98 ms
Sep 12 14:36:14 tlondon pulseaudio[4086]: protocol-native.c: Final latency 379.14 ms = 179.59 ms + 2*9.98 ms + 179.59 ms
Sep 12 14:36:15 tlondon pulseaudio[4086]: sink-input.c: Freeing input 56 "Playback Stream"
Sep 12 14:36:15 tlondon pulseaudio[4086]: client.c: Freed 72 "Pidgin"
Sep 12 14:36:15 tlondon pulseaudio[4086]: protocol-native.c: Connection died.
Sep 12 14:36:24 tlondon pulseaudio[4086]: client.c: Created 73 "Native client (UNIX socket client)"
Sep 12 14:36:24 tlondon pulseaudio[4086]: protocol-native.c: Got credentials: uid=500 gid=500 success=1
Sep 12 14:36:24 tlondon pulseaudio[4086]: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Pidgin.
Sep 12 14:36:24 tlondon pulseaudio[4086]: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Pidgin.
Sep 12 14:36:24 tlondon pulseaudio[4086]: resampler.c: Using resampler 'speex-float-3'
Sep 12 14:36:24 tlondon pulseaudio[4086]: resampler.c: Using float32le as working format.
Sep 12 14:36:24 tlondon pulseaudio[4086]: resampler.c: Choosing speex quality setting 3.
Sep 12 14:36:24 tlondon pulseaudio[4086]: sink-input.c: Created input 57 "Playback Stream" on alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right
Sep 12 14:36:24 tlondon pulseaudio[4086]: protocol-native.c: Requested tlength=199.55 ms, minreq=9.98 ms
Sep 12 14:36:24 tlondon pulseaudio[4086]: protocol-native.c: Final latency 379.14 ms = 179.59 ms + 2*9.98 ms + 179.59 ms
Sep 12 14:36:24 tlondon pulseaudio[4086]: sink-input.c: Freeing input 57 "Playback Stream"
Sep 12 14:36:24 tlondon pulseaudio[4086]: client.c: Freed 73 "Pidgin"
Sep 12 14:36:24 tlondon pulseaudio[4086]: protocol-native.c: Connection died.
Sep 12 14:36:32 tlondon pulseaudio[4086]: client.c: Created 74 "Native client (UNIX socket client)"
Sep 12 14:36:32 tlondon pulseaudio[4086]: protocol-native.c: Got credentials: uid=500 gid=500 success=1
Sep 12 14:36:32 tlondon pulseaudio[4086]: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Pidgin.
Sep 12 14:36:32 tlondon pulseaudio[4086]: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Pidgin.
Sep 12 14:36:32 tlondon pulseaudio[4086]: resampler.c: Using resampler 'speex-float-3'
Sep 12 14:36:32 tlondon pulseaudio[4086]: resampler.c: Using float32le as working format.
Sep 12 14:36:32 tlondon pulseaudio[4086]: resampler.c: Choosing speex quality setting 3.
Sep 12 14:36:32 tlondon pulseaudio[4086]: sink-input.c: Created input 58 "Playback Stream" on alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right
Sep 12 14:36:32 tlondon pulseaudio[4086]: protocol-native.c: Requested tlength=199.55 ms, minreq=9.98 ms
Sep 12 14:36:32 tlondon pulseaudio[4086]: protocol-native.c: Final latency 379.14 ms = 179.59 ms + 2*9.98 ms + 179.59 ms
Sep 12 14:36:32 tlondon pulseaudio[4086]: sink-input.c: Freeing input 58 "Playback Stream"
Sep 12 14:36:32 tlondon pulseaudio[4086]: client.c: Freed 74 "Pidgin"
Sep 12 14:36:32 tlondon pulseaudio[4086]: protocol-native.c: Connection died.
Sep 12 14:37:46 tlondon pulseaudio[4086]: client.c: Created 75 "Native client (UNIX socket client)"
Sep 12 14:37:46 tlondon pulseaudio[4086]: protocol-native.c: Got credentials: uid=500 gid=500 success=1
Sep 12 14:37:46 tlondon pulseaudio[4086]: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Pidgin.
Sep 12 14:37:46 tlondon pulseaudio[4086]: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Pidgin.
Sep 12 14:37:46 tlondon pulseaudio[4086]: resampler.c: Using resampler 'speex-float-3'
Sep 12 14:37:46 tlondon pulseaudio[4086]: resampler.c: Using float32le as working format.
Sep 12 14:37:46 tlondon pulseaudio[4086]: resampler.c: Choosing speex quality setting 3.
Sep 12 14:37:46 tlondon pulseaudio[4086]: sink-input.c: Created input 59 "Playback Stream" on alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right
Sep 12 14:37:46 tlondon pulseaudio[4086]: protocol-native.c: Requested tlength=199.55 ms, minreq=9.98 ms
Sep 12 14:37:46 tlondon pulseaudio[4086]: protocol-native.c: Final latency 379.14 ms = 179.59 ms + 2*9.98 ms + 179.59 ms
Sep 12 14:37:47 tlondon pulseaudio[4086]: shm.c: shm_open() failed: No such file or directory
Sep 12 14:37:47 tlondon pulseaudio[4086]: pstream.c: Failed to import memory block.
Sep 12 14:37:47 tlondon pulseaudio[4086]: sink-input.c: Freeing input 59 "Playback Stream"
Sep 12 14:37:47 tlondon pulseaudio[4086]: client.c: Freed 75 "Pidgin"
Sep 12 14:37:47 tlondon pulseaudio[4086]: protocol-native.c: Connection died.
Sep 12 14:38:12 tlondon pulseaudio[4086]: client.c: Created 76 "Native client (UNIX socket client)"
Sep 12 14:38:12 tlondon pulseaudio[4086]: protocol-native.c: Got credentials: uid=500 gid=500 success=1
Comment 5 Tom London 2008-09-14 14:09:02 EDT
Here is another one below.

I'm checking my old logs, but at least these two occur with pidgin-generated sounds.  In general, I have rhythmbox playing (sometimes muted for, say, 5-30 minutes at a time).

[Checking my old logs doesn't help, as I didn't have debugging enabled until the report above....]

Sep 13 12:57:12 tlondon pulseaudio[3118]: client.c: Created 64 "Native client (UNIX socket client)"
Sep 13 12:57:12 tlondon pulseaudio[3118]: protocol-native.c: Got credentials: uid=500 gid=500 success=1
Sep 13 12:57:12 tlondon pulseaudio[3118]: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Pidgin.
Sep 13 12:57:12 tlondon pulseaudio[3118]: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Pidgin.
Sep 13 12:57:12 tlondon pulseaudio[3118]: resampler.c: Using resampler 'speex-float-3'
Sep 13 12:57:12 tlondon pulseaudio[3118]: resampler.c: Using float32le as working format.
Sep 13 12:57:12 tlondon pulseaudio[3118]: resampler.c: Choosing speex quality setting 3.
Sep 13 12:57:12 tlondon pulseaudio[3118]: sink-input.c: Created input 49 "Playback Stream" on alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right
Sep 13 12:57:12 tlondon pulseaudio[3118]: protocol-native.c: Requested tlength=199.55 ms, minreq=9.98 ms
Sep 13 12:57:12 tlondon pulseaudio[3118]: protocol-native.c: Final latency 379.14 ms = 179.59 ms + 2*9.98 ms + 179.59 ms
Sep 13 12:57:14 tlondon pulseaudio[3118]: shm.c: shm_open() failed: No such file or directory
Sep 13 12:57:14 tlondon pulseaudio[3118]: pstream.c: Failed to import memory block.
Sep 13 12:57:14 tlondon pulseaudio[3118]: sink-input.c: Freeing input 49 "Playback Stream"
Sep 13 12:57:14 tlondon pulseaudio[3118]: client.c: Freed 64 "Pidgin"
Comment 6 Tom London 2008-09-14 15:56:56 EDT
Not sure its relevant, but here are details of /dev/shm on my system.

System has been running for about 3.75 hours, with rhythmbox active most of the time, and pidgin "sounding" intermittantly.

[tbl@tlondon shm]$ ls -lZ /dev/shm
-r--------  tbl tbl unconfined_u:object_r:unconfined_tmpfs_t:s0 pulse-shm-1454783934
-r--------  tbl tbl unconfined_u:object_r:tmpfs_t:s0 pulse-shm-1693118357
-r--------  tbl tbl unconfined_u:object_r:unconfined_tmpfs_t:s0 pulse-shm-2817906901
-r--------  tbl tbl unconfined_u:object_r:unconfined_tmpfs_t:s0 pulse-shm-323609340
[tbl@tlondon shm]$ ls -l /dev/shm
total 848
-r-------- 1 tbl tbl 67108888 2008-09-14 09:10 pulse-shm-1454783934
-r-------- 1 tbl tbl 67108888 2008-09-14 12:49 pulse-shm-1693118357
-r-------- 1 tbl tbl 67108888 2008-09-14 09:10 pulse-shm-2817906901
-r-------- 1 tbl tbl 67108888 2008-09-14 11:55 pulse-shm-323609340
[tbl@tlondon shm]$ 

Current date: 
[tbl@tlondon shm]$ date
Sun Sep 14 12:54:53 PDT 2008
[tbl@tlondon shm]$ 
[tbl@tlondon shm]$ uptime
 12:55:26 up  3:46,  3 users,  load average: 0.34, 0.47, 0.49
[tbl@tlondon shm]$ last | head
tbl      pts/1        :0.0             Sun Sep 14 09:11   still logged in   
tbl      pts/0        :0.0             Sun Sep 14 09:11   still logged in   
tbl      :0                            Sun Sep 14 09:10   still logged in   
tbl      tty7         :0               Sun Sep 14 09:10   still logged in   
reboot   system boot  2.6.27-0.325.rc6 Sun Sep 14 09:09          (03:45)
Comment 7 Tom London 2008-09-18 10:42:32 EDT
Got another one of these just now (while rhythmbox was active playing an mp3).

Not sure what other information would be helpful/useful.

Sep 18 07:30:56 tlondon pulseaudio[3131]: client.c: Created 66 "Native client (UNIX socket client)"
Sep 18 07:30:56 tlondon pulseaudio[3131]: protocol-native.c: Got credentials: uid=500 gid=500 success=1
Sep 18 07:30:56 tlondon pulseaudio[3131]: module-stream-restore.c: Restoring device for stream sink-input-by-application-name:Pidgin.
Sep 18 07:30:56 tlondon pulseaudio[3131]: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Pidgin.
Sep 18 07:30:56 tlondon pulseaudio[3131]: resampler.c: Using resampler 'speex-float-3'
Sep 18 07:30:56 tlondon pulseaudio[3131]: resampler.c: Using float32le as working format.
Sep 18 07:30:56 tlondon pulseaudio[3131]: resampler.c: Choosing speex quality setting 3.
Sep 18 07:30:56 tlondon pulseaudio[3131]: sink-input.c: Created input 47 "Playback Stream" on alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right
Sep 18 07:30:56 tlondon pulseaudio[3131]: protocol-native.c: Requested tlength=199.55 ms, minreq=9.98 ms
Sep 18 07:30:56 tlondon pulseaudio[3131]: protocol-native.c: Final latency 379.14 ms = 179.59 ms + 2*9.98 ms + 179.59 ms
Sep 18 07:30:59 tlondon pulseaudio[3131]: shm.c: shm_open() failed: No such file or directory
Sep 18 07:30:59 tlondon pulseaudio[3131]: pstream.c: Failed to import memory block.
Sep 18 07:30:59 tlondon pulseaudio[3131]: sink-input.c: Freeing input 47 "Playback Stream"
Sep 18 07:30:59 tlondon pulseaudio[3131]: client.c: Freed 66 "Pidgin"
Sep 18 07:30:59 tlondon pulseaudio[3131]: protocol-native.c: Connection died.
Comment 8 Lennart Poettering 2008-09-23 19:21:58 EDT
Can you reproduce this if you turn of SELinux?
Comment 9 Lennart Poettering 2008-09-23 19:23:42 EDT
(I am asking because we have some code in PA that checks /dev/shm from time to time and removes shm segs that belong to apparently dead clients. It might happen that this check doesn't work properly due to SELinux and we remove shm segs of clients that are still around.)
Comment 10 Tom London 2008-09-23 19:40:09 EDT
OK.  I'll test (although it may take me a few days to report, as this appears to happen ever few days or so).

I'll also try to correlate the /var/log/audit/audit.log to see if any of the previous events occurred with SELinux in permissive mode.
Comment 11 Tom London 2008-09-23 19:56:53 EDT
Cross checking /var/log/audit/audit.log (for setenforce times) with /var/log/messages (for above messages) appears to indicate that all occurred when running with SELinux enabled, but then again, I run enabled almost all the time.......

I'll boot permissive for a while.......
Comment 12 Tom London 2008-09-23 20:03:37 EDT
One more thing....

On my system, pulse (and pulse/gconf-helper) run as unconfined_t.  So does pidgin.

But rhythmbox runs as unconfined_execmem_t. (This is needed for the fluendo mp3 codec, if I remember correctly).

Could that "difference" (i.e., unconfined_t vs. unconfined_execmem_t) be "breaking" the code that checks shm?

What does the code do?  Check /proc/PID (or some such).  Something like "lsof"?
Comment 13 Lennart Poettering 2008-09-24 08:52:59 EDT
To be frank I have no clue about SELinux except that it always breaks things and that Dan Walsh maintains some policy file that usually is broken.

This is the code that does the cleanup:

http://git.0pointer.de/?p=pulseaudio.git;a=blob;f=src/pulsecore/shm.c;h=b2997575d99cc91d2df966bf5573d0e804532eef;hb=HEAD#l321

(i.e. function pa_shm_cleanup())

We basically check with kill() that the PID stored in the shm seg can be killed (or when it cannot be killed that the error is not ESRCH).
Comment 14 Tom London 2008-09-24 15:24:52 EDT
Sorry, I still get this even when I boot in permissive mode (i.e., w/ enforcing=0):

Sep 24 11:39:25 tlondon pulseaudio[3227]: module-stream-restore.c: Restoring volume for sink input sink-input-by-application-name:Pidgin.
Sep 24 11:39:25 tlondon pulseaudio[3227]: resampler.c: Using resampler 'speex-float-3'
Sep 24 11:39:25 tlondon pulseaudio[3227]: resampler.c: Using float32le as working format.
Sep 24 11:39:25 tlondon pulseaudio[3227]: resampler.c: Choosing speex quality setting 3.
Sep 24 11:39:25 tlondon pulseaudio[3227]: sink-input.c: Created input 13 "Playback Stream" on alsa_output.pci_8086_27d8_sound_card_0_alsa_playback_0 with sample spec s16le 2ch 22050Hz and channel map front-left,front-right
Sep 24 11:39:25 tlondon pulseaudio[3227]: protocol-native.c: Requested tlength=199.55 ms, minreq=9.98 ms
Sep 24 11:39:25 tlondon pulseaudio[3227]: protocol-native.c: Final latency 379.14 ms = 179.59 ms + 2*9.98 ms + 179.59 ms
Sep 24 11:39:27 tlondon pulseaudio[3227]: shm.c: shm_open() failed: No such file or directory
Sep 24 11:39:27 tlondon pulseaudio[3227]: pstream.c: Failed to import memory block.
Sep 24 11:39:27 tlondon pulseaudio[3227]: sink-input.c: Freeing input 13 "Playback Stream"
Sep 24 11:39:27 tlondon pulseaudio[3227]: client.c: Freed 23 "Pidgin"
Sep 24 11:39:27 tlondon pulseaudio[3227]: protocol-native.c: Connection died.
Comment 15 Tom London 2008-09-24 15:34:25 EDT
BTW, does the code handle the case of "wrapped" or reused pids?  That is, the process that allocated the shm is dead, but the pid of the process is being used by another (unrelated) process?

In that case, I think "kill(pid,0)==0" could be true, but the original process is really gone.

Not this problem, I think, but it would fail to remove "dead" file.
Comment 16 Tom London 2008-09-24 18:38:11 EDT
Suppose another possibility is random number collision (pa_shm_create_rw):

 131         pa_random(&m->id, sizeof(m->id));
 132         segment_name(fn, sizeof(fn), m->id);
 133 
 134         if ((fd = shm_open(fn, O_RDWR|O_CREAT|O_EXCL, mode & 0444)) < 0) {
 135             pa_log("shm_open() failed: %s", pa_cstrerror(errno));
 136             goto fail;
 137         }

Any chance pa_random() is producing collisons?
Comment 17 Lennart Poettering 2008-10-01 21:29:00 EDT
No, the code should be safe. The only risk is that we detect that an shm seg is still used but actually is not. i.e. we'd leak an shm seg for a bit longer than necessary.

It is very unlikely that we hit random number collisions here. We use /dev/urandom to get the random number which should be a pretty ok RNG. And the number is 32bit wide. The chance to get collisions is thus about 1:80000, if I remember the birthday paradoxon correctly. It's not totally unlikely, but uh, you appear to be able to reproduce this more often then every 80k times?

Hmm, I am really puzzled by this and cannot reproduce this here.

The shm cleanup may be triggered directly via pulseaudio --cleanup-shm btw. Maybe you can use this to trigger the issue more quickly?

Hmm, can I convince you to build the pa rpm yourself and disable them shm seg cleanup stuff while doing so? (i.e. simply put a "return 0" as the first like fo pa_shm_cleanup() in pulsecore/shhm.c.) If this problem persists we at least know that it is unrelated to the cleanup routine.
Comment 18 Lennart Poettering 2008-10-01 21:33:00 EDT
Hmm, I wonder if this is actually a race... i.e. the client sets up shm, connects to pa via socket, sends some data over the socket, closes the socket without waiting until it is okeyed, removes the shm. Then, PA comes, reads from the socket, tries to open the shm seg referred to in the data it just read. But the shm seg ain't there anymore.

Is this always the sample client? i.e. Pidgin?
Comment 19 Lennart Poettering 2008-10-01 21:34:04 EDT
s/sample/same/

hehe, i guess that typo is a sign that i am doing too much audio stuff... ;-)
Comment 20 Lennart Poettering 2008-10-01 21:37:39 EDT
oh, and how is pidgin configured? what kind of audio output did you select?
Comment 21 Tom London 2008-10-02 09:27:45 EDT
Sure, you can convince me ;)

I'll pull the rawhide source rpm and build.

A few questions:

1. My quick reading of the code indicates that there are 2 places where this error might be generated: pa_shm_attach_ro() and pa_shm_create_rw(). I would usually make the error messages "unique", unless you are certain which leg of the code this is coming from.

2. The rawhide source rpm seems to want to build "the entire pulse world". Are all these binary packages needed to test this?

To answer your questions:

I believe I've only seen this with pidgin; but I almost always have rhythmbox running as well.  So I'm guessing its pidgin+rhythmbox.

Sound configuration of pidgin: I believe it is "stock" rawhide. Sound method says "Automatic", Enable sound when conversation has focus is selected, and Enable sound has "Only when available" selected.

I'll play with the latter 2 options to see if I can get it to "do more sounds".

And I'll set up a script/loop to run "pulseaudio --cleanup-shm" to see if I can trigger this more often.

Haven't seen this in the last 2 days, BTW.
Comment 22 Tom London 2008-10-02 09:56:42 EDT
OK. Downloaded src rpm and the associated devel rpms.  Building now.

I applied the following patch to "disambiguate" the error message.

--- pulseaudio-0.9.12/src/pulsecore/shm.c.orig	2008-22:06:10.000000000 -0400
+++ pulseaudio-0.9.12/src/pulsecore/shm.c	2008-09-15 22:08:39.000000000 -0400
@@ -132,7 +132,7 @@
         segment_name(fn, sizeof(fn), m->id);
 
         if ((fd = shm_open(fn, O_RDWR|O_CREAT|O_EXCL, mode & 0444)) < 0) {
-            pa_log("shm_open() failed: %s", pa_cstrerror(errno));
+            pa_log("pa_shm_create_rw(): shm_open() failed: %s", pa_cstrerror(errno));
             goto fail;
         }
 
@@ -273,7 +273,7 @@
 
     if ((fd = shm_open(fn, O_RDONLY, 0)) < 0) {
         if (errno != EACCES)
-            pa_log("shm_open() failed: %s", pa_cstrerror(errno));
+            pa_log("pa_shm_attach_ro(): shm_open() failed: %s", pa_cstrerror(errno));
         goto fail;
     }
 
When it completes building,  I'll install and start testing.
Comment 23 Tom London 2008-10-03 13:57:28 EDT
I slightly modified the above patch adding some logging in the case the code unlinks a shm file.  Patch below.

I've been running this for about a day or so, but I have not yet been able to reproduce the issue.

All day yesterday, I ran the following script as my normal user:

while :
do
	date
	pulseaudio --cleanup-shm
	echo; echo; echo; echo
	sleep 20
done >shm-log.txt 2>&1&

Here are the last 2 outputs from '--cleanup-shm':

Thu Oct  2 17:31:54 PDT 2008
I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
I: caps.c: Dropping root priviliges.
I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
D: main.c: Started as real root: no, suid root: yes
I: main.c: We're in the group 'pulse-rt', allowing high-priority scheduling.
I: main.c: Giving up CAP_NICE
D: main.c: Can realtime: yes, can high-priority: yes




Thu Oct  2 17:32:14 PDT 2008
I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
I: caps.c: Dropping root priviliges.
I: caps.c: Limited capabilities successfully to CAP_SYS_NICE.
D: main.c: Started as real root: no, suid root: yes
I: main.c: We're in the group 'pulse-rt', allowing high-priority scheduling.
I: main.c: Giving up CAP_NICE
D: main.c: Can realtime: yes, can high-priority: yes
W: shm.c: pa_shm_cleanup(): removing /pulse-shm-4185968735
W: shm.c: pa_shm_cleanup(): removing /pulse-shm-65240405
W: shm.c: pa_shm_cleanup(): removing /pulse-shm-144283580
W: shm.c: pa_shm_cleanup(): removing /pulse-shm-1194881054


This last is produced during "shutdown", otherwise there are no cleanup events logged.

Not completely clear why this problem "stopped" or how to make it happen again (now that I'm watching....).

I'll continue watching this today, but without the separate cleanup script.


--- pulseaudio-0.9.12/src/pulsecore/shm.c.orig	2008-22:06:10.000000000 -0400
+++ pulseaudio-0.9.12/src/pulsecore/shm.c	2008-09-15 22:08:39.000000000 -0400
@@ -132,7 +132,7 @@
         segment_name(fn, sizeof(fn), m->id);
 
         if ((fd = shm_open(fn, O_RDWR|O_CREAT|O_EXCL, mode & 0444)) < 0) {
-            pa_log("shm_open() failed: %s", pa_cstrerror(errno));
+            pa_log("pa_shm_create_rw(): shm_open() failed: %s", pa_cstrerror(errno));
             goto fail;
         }
 
@@ -273,7 +273,7 @@
 
     if ((fd = shm_open(fn, O_RDONLY, 0)) < 0) {
         if (errno != EACCES)
-            pa_log("shm_open() failed: %s", pa_cstrerror(errno));
+            pa_log("pa_shm_attach_ro(): shm_open() failed: %s", pa_cstrerror(errno));
         goto fail;
     }
 
@@ -373,6 +373,9 @@
         /* Ok, the owner of this shms segment is dead, so, let's remove the segment */
         segment_name(fn, sizeof(fn), id);
 
+#if 1
+	pa_log_warn("pa_shm_cleanup(): removing %s\n", fn);
+#endif
         if (shm_unlink(fn) < 0 && errno != EACCES && errno != ENOENT)
             pa_log_warn("Failed to remove SHM segment %s: %s\n", fn, pa_cstrerror(errno));
     }
Comment 24 Tom London 2008-10-06 09:55:02 EDT
Running my modified version of pulseaudio (patch as in #23), I was not able to reproduce running my modified version of pulseaudio.

Updated this morning to 

pulseaudio-libs-0.9.13-1.fc10.i386
pulseaudio-module-gconf-0.9.13-1.fc10.i386
pulseaudio-debuginfo-0.9.12-6.prep2.fc10.i386   [Yeah, I know this is the old version....]
pulseaudio-libs-glib2-0.9.13-1.fc10.i386
pulseaudio-0.9.13-1.fc10.i386
pulseaudio-module-x11-0.9.13-1.fc10.i386
pulseaudio-core-libs-0.9.13-1.fc10.i386
pulseaudio-utils-0.9.13-1.fc10.i386
pulseaudio-esound-compat-0.9.13-1.fc10.i386

I'll continue to monitor with this version.  If I see the stock warning, I'll apply patch, build, install and monitor.....

I'm really trying to figure out what, if anything, changed in the last week or so to make this "stop happening".

The "pulling at straws" hypothesis I came up with is nsplugin.  I used to get random "alert notifications" from google messaging that slowed down this past week. 

Sorry I haven't been able to help out here.....
Comment 25 Tom London 2008-10-08 09:56:51 EDT
Created attachment 319752 [details]
/var/log/messages segment showing "shm.c: shm_open() failed: No such file or directory"

Scanning my logs, I got 2 more instances of this on 6 October while running "stock" pulseaudio-0.9.13-1.fc10.i386.

I tried to include a larger context from /var/log/messages.

Both occurred within a 6 or 7 minute interval.
Comment 26 Tom London 2008-10-13 17:49:49 EDT
Some more info and a question.

I just brought up a new install from the F10-Spin CD on a Thinkpad X61 (versus the X60 I've been running).

This system is running an X86_64 kernel (and apps).

I did not see this problem running with this system for several days until just now:

Oct 13 14:37:08 tlondon pulseaudio[3267]: shm.c: shm_open() failed: No such file or directory
Oct 13 14:37:08 tlondon pulseaudio[3267]: pstream.c: Failed to import memory block.

The most recent change I made was to change /etc/fstab to force /tmp to mount on a tmpfs (along with /dev/shm):

tmpfs                   /tmp                    tmpfs   defaults        0 0
tmpfs                   /dev/shm                tmpfs   defaults        0 0


I've run my older system with /tmp mounted on tmpfs for months, so the two systems are now the same (wrt /tmp).

Don't suppose its possible that there is some sort of issue with 2 tmpfs?

[Yeah, I know I'm pulling at straws....]
Comment 27 Tom London 2008-10-16 09:25:43 EDT
(In reply to comment #26)
> Some more info and a question.
> 
> I just brought up a new install from the F10-Spin CD on a Thinkpad X61 (versus
> the X60 I've been running).
> 
> This system is running an X86_64 kernel (and apps).
> 
> I did not see this problem running with this system for several days until just
> now:
> 
> Oct 13 14:37:08 tlondon pulseaudio[3267]: shm.c: shm_open() failed: No such
> file or directory
> Oct 13 14:37:08 tlondon pulseaudio[3267]: pstream.c: Failed to import memory
> block.
> 
> The most recent change I made was to change /etc/fstab to force /tmp to mount
> on a tmpfs (along with /dev/shm):
> 
> tmpfs                   /tmp                    tmpfs   defaults        0 0
> tmpfs                   /dev/shm                tmpfs   defaults        0 0
> 
> 
> I've run my older system with /tmp mounted on tmpfs for months, so the two
> systems are now the same (wrt /tmp).
> 
> Don't suppose its possible that there is some sort of issue with 2 tmpfs?
> 
> [Yeah, I know I'm pulling at straws....]

Consider this wrong.  Sorry for the noise. (I still get this with only one tmpfs mount...)

I get this
Comment 28 Lennart Poettering 2008-10-24 16:11:03 EDT
Uh? I don't see how this could be a blocker for F10?
Comment 29 Andre Costa 2008-10-25 09:15:22 EDT
Hi,

I'm also seeing these here on my fully updated 64bit F9 system:

Oct 24 16:23:51 localhost pulseaudio[2725]: shm.c: shm_open() failed: No such file or directory
Oct 24 16:23:51 localhost pulseaudio[2725]: pstream.c: Failed to import memory block.

When it happens, pulseaudio seems to get stuck. Video playing on totem on this situation causes video to progress very slowly, like 1 frame/s, and there's no sound at all.

I'm not sure what exactly triggers this, but I'm usually listening to music on rhythmbox and doing some memory-intensive stuff on Eclipse (Java). Sometimes there might be some flash video playing on Firefox as well. "pulseaudio -k; pulseaudio -D" seems to fix the problem. System has 2GB RAM, pulseaudio is latest avaliable for F9 (pulseaudio-0.9.10-2.fc9.x86_64).

Let me know if I can provide any additional info.

BTW: I upgraded Flash to version 10, and I use nspluginwrapper and libflashsupport, but I read somewhere that it shouldn't be necessary with Flash 10 and actually might even cause problems. Should I drop libflashsupport?
Comment 30 Bug Zapper 2008-11-25 22:01:45 EST
This bug appears to have been reported against 'rawhide' during the Fedora 10 development cycle.
Changing version to '10'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 31 Bug Zapper 2009-11-18 03:22:45 EST
This message is a reminder that Fedora 10 is nearing its end of life.
Approximately 30 (thirty) days from now Fedora will stop maintaining
and issuing updates for Fedora 10.  It is Fedora's policy to close all
bug reports from releases that are no longer maintained.  At that time
this bug will be closed as WONTFIX if it remains open with a Fedora 
'version' of '10'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version prior to Fedora 10's end of life.

Bug Reporter: Thank you for reporting this issue and we are sorry that 
we may not be able to fix it before Fedora 10 is end of life.  If you 
would still like to see this bug fixed and are able to reproduce it 
against a later version of Fedora please change the 'version' of this 
bug to the applicable version.  If you are unable to change the version, 
please add a comment here and someone will do it for you.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events.  Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

The process we are following is described here: 
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 32 Bug Zapper 2009-12-18 01:22:57 EST
Fedora 10 changed to end-of-life (EOL) status on 2009-12-17. Fedora 10 is 
no longer maintained, which means that it will not receive any further 
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of 
Fedora please feel free to reopen this bug against that version.

Thank you for reporting this bug and we are sorry it could not be fixed.

Note You need to log in before you can comment on or make changes to this bug.