Ubuntu
hal package

hal-acl-tool crashed with SIGSEGV in polkit_authorization_db_is_session_authorized()

Bug #361223 reported by mrokos on 2009-04-14

This bug report is a duplicate of: Bug #357161: hal-acl-tool crashed with SIGSEGV in polkit_authorization_db_is_session_authorized(). Edit Remove

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	hal (Ubuntu)	New	Medium	Unassigned

Bug Description

Binary package hint: hal

hi
i`m runing under 9.05 with all avilble updates,
MoBo asus a7n8x e deluxe
CPU Athlon Barton 3200+
2x512 Ram

and thats all :)
when i come back to my computer after 15 minutes brake, a saw this report.
BR
Ł

ProblemType: Crash
Architecture: i386
CrashCounter: 1
DistroRelease: Ubuntu 9.04
ExecutablePath: /usr/lib/hal/hal-acl-tool
NonfreeKernelModules: nvidia
Package: hal 0.5.12~rc1+git20090403-0ubuntu1
ProcAttrCurrent: unconfined
ProcCmdline: /usr/lib/hal/hal-acl-tool --reconfigure
ProcEnviron: PATH=(custom, no user)
Signal: 11
SourcePackage: hal
StacktraceTop:
?? () from /usr/lib/libpolkit.so.2
?? () from /usr/lib/libpolkit.so.2
polkit_authorization_db_is_session_authorized ()
polkit_context_is_session_authorized ()
polkit_context_can_session_do_action ()
Title: hal-acl-tool crashed with SIGSEGV in polkit_authorization_db_is_session_authorized()
Uname: Linux 2.6.28-11-generic i686
UserGroups:

Tags:

Revision history for this message

mrokos (l-mroczkowski) wrote on 2009-04-14:

Dependencies.txt Edit (1.9 KiB, text/plain; charset="utf-8")
Disassembly.txt Edit (484 bytes, text/plain; charset="utf-8")
ProcMaps.txt Edit (4.7 KiB, text/plain; charset="utf-8")
ProcStatus.txt Edit (720 bytes, text/plain; charset="utf-8")
Registers.txt Edit (465 bytes, text/plain; charset="utf-8")
Stacktrace.txt Edit (553 bytes, text/plain; charset="utf-8")
ThreadStacktrace.txt Edit (580 bytes, text/plain; charset="utf-8")

visibility:

private → public

Revision history for this message

Apport retracing service (apport) wrote on 2009-04-14: Stacktrace.txt (retraced)

Stacktrace.txt (retraced) Edit (2.6 KiB, text/plain)

StacktraceTop:?? () from /usr/lib/libpolkit.so.2
_internal_foreach (authdb=0x9113048,
polkit_authorization_db_is_session_authorized (
polkit_context_is_session_authorized (pk_context=0x9113008,
polkit_context_can_session_do_action (pk_context=0x9113008,

Revision history for this message

Apport retracing service (apport) wrote on 2009-04-14: ThreadStacktrace.txt (retraced)

ThreadStacktrace.txt (retraced) Edit (2.6 KiB, text/plain)

Changed in hal (Ubuntu):
importance:	Undecided → Medium
tags:	removed: need-i386-retrace

Revision history for this message

Ian! D. Allen (idallen) wrote on 2009-04-16:

Download full text (11.9 KiB)

Upgraded from 8.04 to 8.10 and found a high load average and huge numbers
of "polkit-read-aut" called from "hal-acl-tool" in my lastcomm logs:

# lastcomm | grep "Apr 14 20:46" | wc -l
9772

# lastcomm | grep "Apr 14 20:46" | grep -c polkit-read-aut
9591

# lastcomm | grep "Apr 14 20:46" | grep -c hal-acl-tool
32

The command line is actually "hal-acl-tool --reconfigure" which calls
polkit-read-auth-helper (over and over and over!).

To slow this down, I replaced /usr/lib/policykit/polkit-read-auth-helper
with a shell script that dumped some environment into a file and did a
"sleep 1" before calling the real binary (renamed to "polkit-ian").
That sleep slowed things down and helped the load average a bit:

# lastcomm | grep "Apr 15 20:40" | wc -l
539

#~[10127] lastcomm | grep "Apr 15 20:40" | grep -c 'polkit-ian'
59

# lastcomm | grep "Apr 15 20:40" | grep -c 'hal-acl-tool'
3

but now I get "X" entries beside all the hal-acl-tool calls:

# lastcomm | grep hal-acl-tool | wc -l
2364

# lastcomm | grep hal-acl-tool | grep X | wc -l
2364

# lastcomm | grep hal-acl-tool | grep X | head -2
hal-acl-tool X root ?? 0.01 secs Wed Apr 15 20:44
hal-acl-tool X root ?? 0.01 secs Wed Apr 15 20:41

I modified my script to run an strace of polkit-read-auth-helper to see
what it was doing 9,772 times per minute and here's one of those dumps:

# grep '^open\|^stat\|^access' /tmp/idebug3.24683
access("/etc/suid-debug", F_OK) = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK) = 0
access("/etc/ld.so.preload", R_OK) = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/usr/local/lib/libpolkit-dbus.so.2", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/lib/libpthread.so.0", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/lib/libc.so.6", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/lib/libdbus-1.so.3", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/usr/local/lib/libpolkit.so.2", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/lib/libselinux.so.1", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/usr/local/lib/libexpat.so.1", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/lib/libdl.so.2", O_RDONLY) = 3
open("/etc/selinux/config", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
statfs64("/selinux", 84, 0xbfe85500) = -1 ENOENT (No such file or directory)
open("/proc/mounts", O_RDONLY|O_LARGEFILE) = 3
open("/etc/nsswitch.conf", O_RDONLY) = 3
open("/etc/ld.so.cache", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/lib/libnss_compat.so.2", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/lib/libnsl.so.1", O_RDONLY) = 3
open("/etc/ld.so.cache", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/lib/libnss_nis.so.2", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK) = 0
open("/lib/libnss_files.so.2", O_RDONLY) = 3
open("/etc/group", O_RDONLY|0x80000 /* O_??? */) = 3
open("/etc/passwd", O_RDO...

Upgraded from 8.04 to 8.10 and found a high load average and huge numbers
of "polkit-read-aut" called from "hal-acl-tool" in my lastcomm logs:

# lastcomm | grep "Apr 14 20:46" | wc -l
9772

# lastcomm | grep "Apr 14 20:46" | grep -c polkit-read-aut
9591

# lastcomm | grep "Apr 14 20:46" | grep -c hal-acl-tool
32

The command line is actually "hal-acl-tool --reconfigure" which calls
polkit-read-auth-helper (over and over and over!).

# lastcomm | grep "Apr 15 20:40" | wc -l
539

#~[10127] lastcomm | grep "Apr 15 20:40" | grep -c 'polkit-ian'
59

# lastcomm | grep "Apr 15 20:40" | grep -c 'hal-acl-tool'
3

but now I get "X" entries beside all the hal-acl-tool calls:

# lastcomm | grep hal-acl-tool | wc -l
2364

# lastcomm | grep hal-acl-tool | grep X | wc -l
2364

# lastcomm | grep hal-acl-tool | grep X | head -2
hal-acl-tool         X root     ??         0.01 secs Wed Apr 15 20:44
hal-acl-tool         X root     ??         0.01 secs Wed Apr 15 20:41

I modified my script to run an strace of polkit-read-auth-helper to see
what it was doing 9,772 times per minute and here's one of those dumps:

# grep '^open\|^stat\|^access' /tmp/idebug3.24683
access("/etc/suid-debug", F_OK)         = -1 ENOENT (No such file or directory)
access("/etc/ld.so.nohwcap", F_OK)      = 0
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/usr/local/lib/libpolkit-dbus.so.2", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/lib/libpthread.so.0", O_RDONLY)  = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/lib/libc.so.6", O_RDONLY)        = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/lib/libdbus-1.so.3", O_RDONLY)   = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/usr/local/lib/libpolkit.so.2", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/lib/libselinux.so.1", O_RDONLY)  = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/usr/local/lib/libexpat.so.1", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/lib/libdl.so.2", O_RDONLY)       = 3
open("/etc/selinux/config", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
statfs64("/selinux", 84, 0xbfe85500)    = -1 ENOENT (No such file or directory)
open("/proc/mounts", O_RDONLY|O_LARGEFILE) = 3
open("/etc/nsswitch.conf", O_RDONLY)    = 3
open("/etc/ld.so.cache", O_RDONLY)      = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/lib/libnss_compat.so.2", O_RDONLY) = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/lib/libnsl.so.1", O_RDONLY)      = 3
open("/etc/ld.so.cache", O_RDONLY)      = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/lib/libnss_nis.so.2", O_RDONLY)  = 3
access("/etc/ld.so.nohwcap", F_OK)      = 0
open("/lib/libnss_files.so.2", O_RDONLY) = 3
open("/etc/group", O_RDONLY|0x80000 /* O_??? */) = 3
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 3
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 3
stat64("/var/run/PolicyKit/user-idallen.auths", 0xbfe85288) = -1 ENOENT (No such file or directory)
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 3
stat64("/var/lib/PolicyKit/user-idallen.auths", 0xbfe85288) = -1 ENOENT (No such file or directory)

Where do I start trying to debug this looping problem?
I am *not* running Gnome or GDM.  I use vtwm via "startx" after I log in.

Various environment details follow:

Linux idallen 2.6.27-11-generic #1 SMP Wed Apr 1 20:57:48 UTC 2009 i686 GNU/Linux

LSB Version:	core-2.0-ia32:core-2.0-noarch:core-3.0-ia32:core-3.0-noarch:core-3.1-ia32:core-3.1-noarch:core-3.2-ia32:core-3.2-noarch:cxx-3.0-ia32:cxx-3.0-noarch:cxx-3.1-ia32:cxx-3.1-noarch:cxx-3.2-ia32:cxx-3.2-noarch:desktop-3.1-ia32:desktop-3.1-noarch:desktop-3.2-ia32:desktop-3.2-noarch:graphics-2.0-ia32:graphics-2.0-noarch:graphics-3.0-ia32:graphics-3.0-noarch:graphics-3.1-ia32:graphics-3.1-noarch:graphics-3.2-ia32:graphics-3.2-noarch:languages-3.2-ia32:languages-3.2-noarch:multimedia-3.2-ia32:multimedia-3.2-noarch:printing-3.2-ia32:printing-3.2-noarch:qt4-3.1-ia32:qt4-3.1-noarch
Distributor ID:	Ubuntu
Description:	Ubuntu 8.10
Release:	8.10
Codename:	intrepid

processor	: 0
vendor_id	: AuthenticAMD
cpu family	: 6
model		: 10
model name	: AMD Athlon(tm) XP 3200+
stepping	: 0
cpu MHz		: 2204.956
cache size	: 512 KB
fdiv_bug	: no
hlt_bug		: no
f00f_bug	: no
coma_bug	: no
fpu		: yes
fpu_exception	: yes
cpuid level	: 1
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 mmx fxsr sse syscall mmxext 3dnowext 3dnow up
bogomips	: 4409.91
clflush size	: 32
power management: ts

MemTotal:      3112188 kB
MemFree:        391260 kB
Buffers:         55416 kB
Cached:        1800424 kB
SwapCached:     235992 kB
Active:        1557140 kB
Inactive:      1059568 kB
HighTotal:     2228160 kB
HighFree:       120008 kB
LowTotal:       884028 kB
LowFree:        271252 kB
SwapTotal:     3421836 kB
SwapFree:      2954456 kB
Dirty:             468 kB
Writeback:           0 kB
AnonPages:      751444 kB
Mapped:          61820 kB
Slab:            71360 kB
SReclaimable:    37612 kB
SUnreclaim:      33748 kB
PageTables:       6212 kB
NFS_Unstable:        0 kB
Bounce:              0 kB
WritebackTmp:        0 kB
CommitLimit:   4977928 kB
Committed_AS:  1650916 kB
VmallocTotal:   110584 kB
VmallocUsed:      8564 kB
VmallocChunk:   101456 kB
HugePages_Total:     0
HugePages_Free:      0
HugePages_Rsvd:      0
HugePages_Surp:      0
Hugepagesize:     4096 kB
DirectMap4k:     32768 kB
DirectMap4M:    884736 kB

CPU0       
  0:        124   IO-APIC-edge      timer
  1:     270972   IO-APIC-edge      i8042
  3:          4   IO-APIC-edge    
  4:          4   IO-APIC-edge    
  7:          0   IO-APIC-edge      parport0
  8:          5   IO-APIC-edge      rtc0
  9:          0   IO-APIC-fasteoi   acpi
 14:    3054864   IO-APIC-edge      pata_amd
 15:    2544541   IO-APIC-edge      pata_amd
 16:    1316215   IO-APIC-fasteoi   pata_pdc2027x
 17:   34844118   IO-APIC-fasteoi   eth1, aic7xxx
 18:   29859724   IO-APIC-fasteoi   sata_sil
 19:       1404   IO-APIC-fasteoi 
 20:     988281   IO-APIC-fasteoi   ohci_hcd:usb2, NVidia nForce2
 21:     844946   IO-APIC-fasteoi   ohci_hcd:usb1, ohci1394
 22:   31277671   IO-APIC-fasteoi   ehci_hcd:usb3, eth0
NMI:          0   Non-maskable interrupts
LOC:   86309518   Local timer interrupts
RES:          0   Rescheduling interrupts
CAL:          0   function call interrupts
TLB:          0   TLB shootdowns
SPU:          0   Spurious interrupts
ERR:          0
MIS:          0

Module                  Size  Used by
iptable_nat            13448  0 
nls_cp437              13696  0 
isofs                  40228  0 
iptable_mangle         10880  0 
af_packet              25728  0 
drbd                  228992  0 
vboxdrv                71576  0 
ipt_ULOG               15268  1 
nfsd                  230768  13 
auth_rpcgss            42656  1 nfsd
exportfs               12544  1 nfsd
nf_conntrack_netlink    24320  0 
nf_nat                 25368  2 iptable_nat,nf_conntrack_netlink
ppdev                  15748  0 
nf_conntrack_ipv4      21900  3 iptable_nat,nf_nat
nf_conntrack           72032  4 iptable_nat,nf_conntrack_netlink,nf_nat,nf_conntrack_ipv4
nfnetlink              12184  3 nf_conntrack_netlink
cpufreq_userspace      11396  0 
cpufreq_powersave       9856  0 
cpufreq_ondemand       14988  0 
cpufreq_conservative    14600  0 
cpufreq_stats          13188  0 
freq_table             12672  2 cpufreq_ondemand,cpufreq_stats
sbs                    19464  0 
sbshc                  13440  1 sbs
video                  25232  0 
output                 11008  1 video
pci_slot               12680  0 
container              11520  0 
wmi                    14504  0 
battery                18436  0 
rfcomm                 44560  0 
l2cap                  30464  3 rfcomm
bluetooth              61924  2 rfcomm,l2cap
ext2                   72584  0 
mga                    68608  0 
drm                    86056  1 mga
lock_dlm               22948  0 
gfs2                  367404  1 lock_dlm
dlm                   125452  1 lock_dlm
configfs               33688  2 dlm
nfs                   269544  0 
lockd                  71976  2 nfsd,nfs
nfs_acl                11264  2 nfsd,nfs
sunrpc                197088  13 nfsd,auth_rpcgss,nfs,lockd,nfs_acl
iptable_filter         10752  0 
ip_tables              19600  3 iptable_nat,iptable_mangle,iptable_filter
x_tables               22916  3 iptable_nat,ipt_ULOG,ip_tables
ac                     12292  0 
sbp2                   29324  0 
lp                     17156  0 
matrox_w1              11392  0 
wire                   29064  1 matrox_w1
pcspkr                 10624  0 
evdev                  17696  3 
snd_intel8x0           37532  0 
snd_ac97_codec        111652  1 snd_intel8x0
ac97_bus                9856  1 snd_ac97_codec
snd_pcm_oss            46848  0 
snd_mixer_oss          22784  1 snd_pcm_oss
snd_pcm                83204  3 snd_intel8x0,snd_ac97_codec,snd_pcm_oss
snd_seq_dummy          10884  0 
parport_pc             39332  1 
parport                42604  3 ppdev,lp,parport_pc
snd_seq_oss            38528  0 
snd_seq_midi           14336  0 
snd_rawmidi            29824  1 snd_seq_midi
snd_seq_midi_event     15232  2 snd_seq_oss,snd_seq_midi
snd_seq                57776  6 snd_seq_dummy,snd_seq_oss,snd_seq_midi,snd_seq_midi_event
snd_timer              29960  2 snd_pcm,snd_seq
snd_seq_device         15116  5 snd_seq_dummy,snd_seq_oss,snd_seq_midi,snd_rawmidi,snd_seq
button                 14224  0 
shpchp                 38036  0 
pci_hotplug            34976  1 shpchp
snd                    63268  10 snd_intel8x0,snd_ac97_codec,snd_pcm_oss,snd_mixer_oss,snd_pcm,snd_seq_oss,snd_rawmidi,snd_seq,snd_timer,snd_seq_device
soundcore              15328  1 snd
i2c_nforce2            14468  0 
snd_page_alloc         16136  2 snd_intel8x0,snd_pcm
nvidia_agp             14492  1 
agpgart                42184  2 drm,nvidia_agp
i2c_core               31892  1 i2c_nforce2
ext3                  133256  5 
jbd                    55828  1 ext3
mbcache                16004  2 ext2,ext3
st                     45212  0 
pata_acpi              12160  0 
pata_amd               18564  0 
osst                   59804  0 
sr_mod                 22212  0 
cdrom                  43168  1 sr_mod
sd_mod                 42392  10 
crc_t10dif              9984  1 sd_mod
sg                     39732  0 
usb_storage            82624  0 
usbhid                 35840  1 
hid                    50560  1 usbhid
libusual               30356  1 usb_storage
ohci1394               37936  0 
pata_pdc2027x          15876  2 
ata_generic            12932  0 
sata_sil               15752  4 
ieee1394               96324  2 sbp2,ohci1394
aic7xxx               152792  0 
scsi_transport_spi     30464  1 aic7xxx
libata                178208  5 pata_acpi,pata_amd,pata_pdc2027x,ata_generic,sata_sil
3c59x                  48936  0 
mii                    13440  1 3c59x
skge                   48144  0 
scsi_mod              155212  10 sbp2,st,osst,sr_mod,sd_mod,sg,usb_storage,aic7xxx,scsi_transport_spi,libata
dock                   16656  1 libata
ehci_hcd               43788  0 
ohci_hcd               32016  0 
forcedeth              61328  0 
usbcore               149488  7 usb_storage,usbhid,libusual,ehci_hcd,ohci_hcd
dm_mirror              27008  0 
dm_log                 17924  1 dm_mirror
dm_snapshot            26276  0 
dm_mod                 63432  3 dm_mirror,dm_log,dm_snapshot
thermal                23708  0 
processor              42156  1 thermal
fan                    12548  0 
nbd                    18960  0 
fbcon                  47648  0 
tileblit               10880  1 fbcon
font                   16512  1 fbcon
bitblit                13824  1 fbcon
softcursor              9984  1 bitblit
fuse                   60828  1

Revision history for this message

Ian! D. Allen (idallen) wrote on 2009-04-16:

Download full text (15.7 KiB)

The sleep in polkit-read-auth-helper is critical in changing the behaviour
of hal-acl-tool. (Looking into the strace of hal-acl-tool, I wonder if
this is due to hal-acl-tool using real-time signals, e.g. SIGRTMIN, and
thus requiring that polkit-read-auth-helper respond quickly?) If I rename
polkit-read-auth-helper to polkit-ian and replace it with this C program:

int main(int argc, char **argv) {
execv("/usr/lib/policykit/polkit-ian",argv);
}

nothing changes - the load average stays way up and I see the looping of
thousands of polkit-ian called by hal-acl-tool.

An inotify watch shows this repeated over and over:

# inotifywait -m -r /var/run/hald/
Setting up watches. Beware: since -r was given, this may take a while!
Watches established.
/var/run/hald/ CREATE acl-list.7AAKSU
/var/run/hald/ OPEN acl-list.7AAKSU
/var/run/hald/ MODIFY acl-list.7AAKSU
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list.7AAKSU
/var/run/hald/ MOVED_FROM acl-list.7AAKSU
/var/run/hald/ MOVED_TO acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ CREATE acl-list.D908RU
/var/run/hald/ OPEN acl-list.D908RU
/var/run/hald/ MODIFY acl-list.D908RU
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list.D908RU
/var/run/hald/ MOVED_FROM acl-list.D908RU
/var/run/hald/ MOVED_TO acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
[... about 50 lines of output every 10 seconds ...]

# cat /var/run/hald/acl-list
/dev/kvm /org/freedesktop/Hal/devices/kvm u 777
/dev/scd0 /org/freedesktop/Hal/devices/storage_model_CD_ROM_DRIVE_466 u
777
/dev/scd1 /org/freedesktop/Hal/devices/storage_model_CD_RW_GCE_8525B u
777

If I insert "sleep(1);" in front of the execv in the C program, the load
average drops and hal-acl-tool starts exiting badly ("X"):

[...]
polkit-ian root ?? 0.00 secs Thu Apr 16 07:01
hal-acl-tool X root ?? 0.10 secs Thu Apr 16 07:01
polkit-ian root ?? 0.00 secs Thu Apr 16 07:01
[...]

and everything changes in the inotify watch:

# inotifywait -m -r /var/run/hald/
Setting up watches. Beware: since -r was given, this may take a while!
Watches established.
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ OPEN acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ OPEN acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ OPEN acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ OPEN acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ OPEN acl-list
[... ...

The sleep in polkit-read-auth-helper is critical in changing the behaviour
of hal-acl-tool.  (Looking into the strace of hal-acl-tool, I wonder if
this is due to hal-acl-tool using real-time signals, e.g. SIGRTMIN, and
thus requiring that polkit-read-auth-helper respond quickly?)  If I rename
polkit-read-auth-helper to polkit-ian and replace it with this C program:

int main(int argc, char **argv) {
        execv("/usr/lib/policykit/polkit-ian",argv);
}

nothing changes - the load average stays way up and I see the looping of
thousands of polkit-ian called by hal-acl-tool.

# lastcomm
[...]
polkit-ian             root     ??         0.00 secs Thu Apr 16 07:01
polkit-ian             root     ??         0.00 secs Thu Apr 16 07:01
polkit-ian             root     ??         0.00 secs Thu Apr 16 07:01
polkit-ian             root     ??         0.00 secs Thu Apr 16 07:01
hal-acl-tool     S     root     ??         0.13 secs Thu Apr 16 07:00
polkit-ian             root     ??         0.00 secs Thu Apr 16 07:01
polkit-ian             root     ??         0.00 secs Thu Apr 16 07:01
polkit-ian             root     ??         0.00 secs Thu Apr 16 07:01
polkit-ian             root     ??         0.00 secs Thu Apr 16 07:01
[...]

An inotify watch shows this repeated over and over:

# inotifywait -m -r /var/run/hald/
Setting up watches.  Beware: since -r was given, this may take a while!
Watches established.
/var/run/hald/ CREATE acl-list.7AAKSU
/var/run/hald/ OPEN acl-list.7AAKSU
/var/run/hald/ MODIFY acl-list.7AAKSU
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list.7AAKSU
/var/run/hald/ MOVED_FROM acl-list.7AAKSU
/var/run/hald/ MOVED_TO acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ CREATE acl-list.D908RU
/var/run/hald/ OPEN acl-list.D908RU
/var/run/hald/ MODIFY acl-list.D908RU
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list.D908RU
/var/run/hald/ MOVED_FROM acl-list.D908RU
/var/run/hald/ MOVED_TO acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
[... about 50 lines of output every 10 seconds ...]

# cat /var/run/hald/acl-list 
/dev/kvm        /org/freedesktop/Hal/devices/kvm        u       777
/dev/scd0       /org/freedesktop/Hal/devices/storage_model_CD_ROM_DRIVE_466    u
        777
/dev/scd1       /org/freedesktop/Hal/devices/storage_model_CD_RW_GCE_8525B     u
        777

If I insert "sleep(1);" in front of the execv in the C program, the load
average drops and hal-acl-tool starts exiting badly ("X"):

[...]
polkit-ian             root     ??         0.00 secs Thu Apr 16 07:01
hal-acl-tool         X root     ??         0.10 secs Thu Apr 16 07:01
polkit-ian             root     ??         0.00 secs Thu Apr 16 07:01
[...]

and everything changes in the inotify watch:

# inotifywait -m -r /var/run/hald/
Setting up watches.  Beware: since -r was given, this may take a while!
Watches established.
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ OPEN acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ OPEN acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ OPEN acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ OPEN acl-list
/var/run/hald/ CLOSE_WRITE,CLOSE acl-list
/var/run/hald/ OPEN acl-list
[... repeats every 20 seconds ...]

Changing sleep(1) to sleep(10) didn't lengthen the 20-second cycle.
I presume hal-acl-tool has some real-time response requirements that
the sleep(1) defeats, causing it to give up waiting for polkit-ian.

I ran some strace's of both programs, but I think that misbehaves
due to strace not preserving the exit status of the program it calls.
Here's some of the interesting strace output:

In two straces of polkit-read-auth-helper I see it checking for PolicyKit
entries for idallen and root (neither exist):

*********************************************************************
*** excerpts from one strace of polkit-read-auth-helper:
*********************************************************************

open("/etc/group", O_RDONLY|0x80000 /* O_??? */) = 3
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1
   ENOENT (No such file or directory)
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1
   ENOENT (No such file or directory)
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 3
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 3
stat64("/var/run/PolicyKit/user-idallen.auths", 0xbfeab4a8) = -1 ENOENT (No
   such file or directory)
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 3
stat64("/var/lib/PolicyKit/user-idallen.auths", 0xbfeab4a8) = -1 ENOENT (No
   such file or directory)

*********************************************************************
*** excerpts from another strace of polkit-read-auth-helper:
*********************************************************************

open("/etc/group", O_RDONLY|0x80000 /* O_??? */) = 3
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1
   ENOENT (No such file or directory)
connect(3, {sa_family=AF_FILE, path="/var/run/nscd/socket"}, 110) = -1
   ENOENT (No such file or directory)
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 3
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 3
stat64("/var/run/PolicyKit/user-root.auths", 0xbfd52b48) = -1 ENOENT (No
   such file or directory)
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 3
stat64("/var/lib/PolicyKit/user-root.auths", 0xbfd52b48) = -1 ENOENT (No
   such file or directory)

*********************************************************************
*********************************************************************

The straces of hal-acl-tool were more exciting.  Some executions of this
program blocked on an flock().  Those that didn't looped like crazy.
Some finished after looping for a while, some didn't.

*********************************************************************
*** excerpts from one incomplete (killed?) strace of hal-acl-tool:
*********************************************************************

futex(0xbfde1ed0, 0x81 /* FUTEX_??? */, 1) = 0
rt_sigaction(SIGRTMIN, {0xb7cee280, [], SA_SIGINFO}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0xb7cee680, [], SA_RESTART|SA_SIGINFO}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
uname({sys="Linux", node="idallen-oak.home.idallen.ca", ...}) = 0
fstat64(1, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0
ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfde1694) = -1 ENOTTY
   (Inappropriate ioctl for device)
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
   0xb7fc5000
open("/var/run/hald/acl-list", O_RDWR|O_CREAT, 0644) = 3
flock(3, LOCK_EX

*********************************************************************
*** excerpts from another strace of hal-acl-tool:
*********************************************************************

[...]

futex(0xbfc64d50, 0x81 /* FUTEX_??? */, 1) = 0
rt_sigaction(SIGRTMIN, {0xb7c71280, [], SA_SIGINFO}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0xb7c71680, [], SA_RESTART|SA_SIGINFO}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN RT_1], NULL, 8) = 0
getrlimit(RLIMIT_STACK, {rlim_cur=8192*1024, rlim_max=RLIM_INFINITY}) = 0
uname({sys="Linux", node="idallen-oak.home.idallen.ca", ...}) = 0
fstat64(1, {st_mode=S_IFCHR|0666, st_rdev=makedev(1, 3), ...}) = 0
ioctl(1, SNDCTL_TMR_TIMEBASE or TCGETS, 0xbfc64514) = -1 ENOTTY
   (Inappropriate ioctl for device)
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
   0xb7f48000
open("/var/run/hald/acl-list", O_RDWR|O_CREAT, 0644) = 3
flock(3, LOCK_EX)                       = 0
brk(0)                                  = 0x96b9000
brk(0x96da000)                          = 0x96da000
socket(PF_FILE, SOCK_STREAM, 0)         = 4
connect(4, {sa_family=AF_FILE, path=@/var/run/hald/dbus-Y8HN7SGUxI}, 32) = 0
fcntl64(4, F_GETFL)                     = 0x2 (flags O_RDWR)
fcntl64(4, F_SETFL, O_RDWR|O_NONBLOCK)  = 0
fcntl64(4, F_GETFD)                     = 0
fcntl64(4, F_SETFD, FD_CLOEXEC)         = 0
geteuid32()                             = 0
rt_sigaction(SIGPIPE, {SIG_IGN}, {SIG_DFL}, 8) = 0
poll([{fd=4, events=POLLOUT, revents=POLLOUT}], 1, 0) = 1
write(4, "\0", 1)                       = 1
write(4, "AUTH EXTERNAL 30\r\n", 18)    = 18
poll([{fd=4, events=POLLIN, revents=POLLIN}], 1, -1) = 1
read(4, "OK 96277e4797f9a54ffbfef5d649e2c3c9\r\n", 2048) = 37
poll([{fd=4, events=POLLOUT, revents=POLLOUT}], 1, -1) = 1
write(4, "BEGIN\r\n", 7)                = 7
poll([{fd=4, events=POLLIN|POLLOUT, revents=POLLOUT}], 1, -1) = 1

[...]

read(4, 0x96bf278, 2048)                = -1 EAGAIN (Resource temporarily unavai
lable)
open("/etc/PolicyKit/PolicyKit.conf", O_RDONLY|O_LARGEFILE) = 5

[...]

read(5, "", 4096)                       = 0
close(5)                                = 0
open("/usr/share/PolicyKit/policy", O_RDONLY|O_NONBLOCK|O_LARGEFILE|O_DIRECTORY|0x80000) = 5
fstat64(5, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
fcntl64(5, F_GETFD)                     = 0x1 (flags FD_CLOEXEC)
getdents64(5, /* 20 entries */, 4096)   = 1088
stat64("/usr/share/PolicyKit/policy/com.ubuntu.devicedriver.policy", {st_mode=S_IFREG|0644, st_size=2687, ...}) = 0
open("/usr/share/PolicyKit/policy/com.ubuntu.devicedriver.policy", O_RDONLY|O_LARGEFILE) = 6

[...]

close(6)                                = 0
open("/var/lib/PolicyKit-public/com.ubuntu.devicedriver.info.defaults-override", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
open("/var/lib/PolicyKit-public/com.ubuntu.devicedriver.check.defaults-override", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
open("/var/lib/PolicyKit-public/com.ubuntu.devicedriver.update.defaults-override", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
open("/var/lib/PolicyKit-public/com.ubuntu.devicedriver.install.defaults-override", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such file or directory)
stat64("/usr/share/PolicyKit/policy/com.ubuntu.systemservice.policy", {st_mode=S_IFREG|0644, st_size=1899, ...}) = 0
open("/usr/share/PolicyKit/policy/com.ubuntu.systemservice.policy", O_RDONLY|O_LARGEFILE) = 6

[...repeat reading lots of PolicyKit files, then it starts looping...]

open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 5
fcntl64(5, F_GETFD)                     = 0x1 (flags FD_CLOEXEC)
_llseek(5, 0, [0], SEEK_CUR)            = 0
fstat64(5, {st_mode=S_IFREG|0644, st_size=2504, ...}) = 0
mmap2(NULL, 2504, PROT_READ, MAP_SHARED, 5, 0) = 0xb7f34000
_llseek(5, 2504, [2504], SEEK_SET)      = 0
munmap(0xb7f34000, 2504)                = 0
close(5)                                = 0
pipe([5, 6])                            = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
   child_tidptr=0xb7c6c6f8) = 11608
--- SIGCHLD (Child exited) @ 0 (0) ---
close(6)                                = 0
select(6, [5], [], NULL, NULL)          = 1 (in [5])
read(5, "", 4095)                       = 0
close(5)                                = 0
waitpid(11608, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 11608
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 5
_llseek(5, 0, [0], SEEK_CUR)            = 0
fstat64(5, {st_mode=S_IFREG|0644, st_size=2504, ...}) = 0
mmap2(NULL, 2504, PROT_READ, MAP_SHARED, 5, 0) = 0xb7f34000
_llseek(5, 2504, [2504], SEEK_SET)      = 0
munmap(0xb7f34000, 2504)                = 0
close(5)                                = 0
pipe([5, 6])                            = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
   child_tidptr=0xb7c6c6f8) = 11609
close(6)                                = 0
select(6, [5], [], NULL, NULL)          = 1 (in [5])
--- SIGCHLD (Child exited) @ 0 (0) ---
read(5, "", 4095)                       = 0
close(5)                                = 0
waitpid(11609, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 11609

[... repeat 508 more times opening /etc/passwd and cloning until finally: ...]

--- SIGCHLD (Child exited) @ 0 (0) ---
read(5, "", 4095)                       = 0
close(5)                                = 0
waitpid(12124, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 12124
open("/var/run/hald/acl-list", O_RDONLY) = 5
fstat64(5, {st_mode=S_IFREG|0644, st_size=199, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
   0xb7f34000
read(5, "/dev/kvm\t/org/freedesktop/Hal/devices/kvm\tu\t777\n/dev/scd0\t/org/freedesktop/Hal/devices/storage_model_CD_ROM_DRIVE_466\tu\t777\n/dev/scd1\t/org/freedesktop/Hal/devices/storage_model_CD_RW_GCE_8525B\tu\t777\n",
   4096) = 199
read(5, "", 4096)                       = 0
close(5)                                = 0
munmap(0xb7f34000, 4096)                = 0
gettimeofday({1239877992, 5111}, NULL)  = 0
open("/var/run/hald/acl-list.1N9GSU", O_RDWR|O_CREAT|O_EXCL|O_LARGEFILE,
   0666) = 5
open("/usr/lib/charset.alias", O_RDONLY|O_LARGEFILE) = -1 ENOENT (No such
   file or directory)
fcntl64(5, F_GETFL)                     = 0x8002 (flags O_RDWR|O_LARGEFILE)
fstat64(5, {st_mode=S_IFREG|0644, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) =
   0xb7f34000
_llseek(5, 0, [0], SEEK_CUR)            = 0
write(5, "/dev/kvm\t/org/freedesktop/Hal/devices/kvm\tu\t777\n/dev/scd0\t/org/freedesktop/Hal/devices/storage_model_CD_ROM_DRIVE_466\tu\t777\n/dev/scd1\t/org/freedesktop/Hal/devices/storage_model_CD_RW_GCE_8525B\tu\t777\n",
   199) = 199
close(5)                                = 0
munmap(0xb7f34000, 4096)                = 0
rename("/var/run/hald/acl-list.1N9GSU", "/var/run/hald/acl-list") = 0
flock(3, LOCK_UN)                       = 0
close(3)                                = 0
write(1, "11604: attempting to get lock on
   /var/run/hald/acl-list\n\n****************************************************\n11604:
   got lock on /var/run/hald/acl-list\n11604: reconfiguring all
   ACL\'s\n\n****************************************************\n11604:
   releasing lock on /var/run/hald/acl-list\n", 285) = 285
exit_group(0)                           = ?

*********************************************************************
*** excerpts from another incomplete strace of hal-acl-tool:
*********************************************************************

open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 5
fcntl64(5, F_GETFD)                     = 0x1 (flags FD_CLOEXEC)
_llseek(5, 0, [0], SEEK_CUR)            = 0
fstat64(5, {st_mode=S_IFREG|0644, st_size=2504, ...}) = 0
mmap2(NULL, 2504, PROT_READ, MAP_SHARED, 5, 0) = 0xb7ef7000
_llseek(5, 2504, [2504], SEEK_SET)      = 0
munmap(0xb7ef7000, 2504)                = 0
close(5)                                = 0
pipe([5, 6])                            = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
   child_tidptr=0xb7c2f6f8) = 12127
--- SIGCHLD (Child exited) @ 0 (0) ---
close(6)                                = 0
select(6, [5], [], NULL, NULL)          = 1 (in [5])
read(5, "", 4095)                       = 0
close(5)                                = 0
waitpid(12127, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 12127
open("/etc/passwd", O_RDONLY|0x80000 /* O_??? */) = 5
_llseek(5, 0, [0], SEEK_CUR)            = 0
fstat64(5, {st_mode=S_IFREG|0644, st_size=2504, ...}) = 0
mmap2(NULL, 2504, PROT_READ, MAP_SHARED, 5, 0) = 0xb7ef7000
_llseek(5, 2504, [2504], SEEK_SET)      = 0
munmap(0xb7ef7000, 2504)                = 0
close(5)                                = 0
pipe([5, 6])                            = 0
clone(child_stack=0, flags=CLONE_CHILD_CLEARTID|CLONE_CHILD_SETTID|SIGCHLD,
   child_tidptr=0xb7c2f6f8) = 12128
close(6)                                = 0
select(6, [5], [], NULL, NULL)          = 1 (in [5])
--- SIGCHLD (Child exited) @ 0 (0) ---
read(5, "", 4095)                       = 0
close(5)                                = 0
waitpid(12128, [{WIFEXITED(s) && WEXITSTATUS(s) == 0}], 0) = 12128

[... repeat 473 times until killed ...]

In general, the straces of hal-acl-tool showed it looping creating new
processes at a huge rate.  (I presume these to be polkit-read-auth-helper.)

Revision history for this message

James Westby (james-w) wrote on 2009-05-14:

Hi Ian,

I don't see that your problem is to do with the crash that was originally
reported in this bug, so please report a new bug so that they can be
tracked separately.

Thanks,

James

Report a bug

This report contains Public information

Everyone can see this information.

Duplicate of bug #357161 Remove

You are

Subscribing...

Edit bug mail

Other bug subscribers

Bug attachments

Add attachment

Remote bug watches

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

Ubuntuhal package

hal-acl-tool crashed with SIGSEGV in polkit_authorization_db_is_session_authorized()

Bug Description

Other bug subscribers

Bug attachments

Remote bug watches

Ubuntu
hal package