Bug 971046 - GError: Timeout was reached
GError: Timeout was reached
Status: CLOSED WORKSFORME
Product: Fedora
Classification: Fedora
Component: polkit (Show other bugs)
19
ppc64 Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: Miloslav Trmač
Fedora Extras Quality Assurance
abrt_hash:8182d7a303fbd0945c78f39f2e9...
:
Depends On: 971519
Blocks: F19-accepted/F19FinalFreezeException F19PPCFinal/F19PPCFinalBlocker/PPCFinalBlocker
  Show dependency treegraph
 
Reported: 2013-06-05 10:28 EDT by Mark Hamzy
Modified: 2013-12-05 15:51 EST (History)
11 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-12-05 15:51:35 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)
File: anaconda-tb (69.08 KB, text/plain)
2013-06-05 10:28 EDT, Mark Hamzy
no flags Details
File: anaconda.log (1.56 KB, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details
File: backtrace (860 bytes, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details
File: environ (577 bytes, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details
File: ifcfg.log (661 bytes, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details
File: ks.cfg (1.26 KB, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details
File: lsblk_output (1.25 KB, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details
File: nmcli_dev_list (2.79 KB, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details
File: packaging.log (412 bytes, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details
File: program.log (6.95 KB, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details
File: storage.log (638 bytes, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details
File: syslog (50.15 KB, text/plain)
2013-06-05 10:29 EDT, Mark Hamzy
no flags Details

  None (edit)
Description Mark Hamzy 2013-06-05 10:28:52 EDT
Description of problem:
Kickstart installation
The following was filed automatically by anaconda:
anaconda 19.30.2-1 exception report
Traceback (most recent call first):
  File "/usr/lib64/python2.7/site-packages/gi/types.py", line 113, in function
    return info.invoke(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/nm.py", line 436, in _update_settings
    None)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/nm.py", line 414, in nm_update_settings_of_device
    return _update_settings(_device_settings(name), key1, key2, value, default_type_str)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/network.py", line 882, in setOnboot
    nm.nm_update_settings_of_device(devname, 'connection', 'autoconnect', network_data.onboot)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/network.py", line 899, in networkInitialize
    setOnboot(ksdata)
  File "/sbin/anaconda", line 1037, in <module>
    networkInitialize(ksdata)
GError: Timeout was reached

Version-Release number of selected component:
anaconda-19.30.2-1

Additional info:
reporter:       libreport-2.1.4
cmdline:        /usr/bin/python  /sbin/anaconda
cmdline_file:   ro  inst.vnc inst.sshd ip=9.5.114.36::9.5.114.1:255.255.255.0:sharpie.rch.stglabs.ibm.com:eth0:none ip=9.5.114.41::9.5.114.1:255.255.255.0::eth1:none nameserver=9.10.244.100 bootdev=eth0 ks=http://chukar.rch.stglabs.ibm.com/Fedora19-sharpie-lvm_auto-cdrom-minimal-ks.cfg
executable:     /sbin/anaconda
hashmarkername: anaconda
kernel:         3.9.4-300.fc19.ppc64
product:        Fedora
release:        Cannot get release name.
type:           anaconda
version:        19

Truncated backtrace:
Traceback (most recent call last):
  File "/sbin/anaconda", line 1037, in <module>
    networkInitialize(ksdata)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/network.py", line 899, in networkInitialize
    setOnboot(ksdata)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/network.py", line 882, in setOnboot
    nm.nm_update_settings_of_device(devname, 'connection', 'autoconnect', network_data.onboot)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/nm.py", line 414, in nm_update_settings_of_device
    return _update_settings(_device_settings(name), key1, key2, value, default_type_str)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/nm.py", line 436, in _update_settings
    None)
  File "/usr/lib64/python2.7/site-packages/gi/types.py", line 113, in function
    return info.invoke(*args, **kwargs)
GError: Timeout was reached
Comment 1 Mark Hamzy 2013-06-05 10:28:58 EDT
Created attachment 757228 [details]
File: anaconda-tb
Comment 2 Mark Hamzy 2013-06-05 10:29:06 EDT
Created attachment 757231 [details]
File: anaconda.log
Comment 3 Mark Hamzy 2013-06-05 10:29:10 EDT
Created attachment 757233 [details]
File: backtrace
Comment 4 Mark Hamzy 2013-06-05 10:29:13 EDT
Created attachment 757234 [details]
File: environ
Comment 5 Mark Hamzy 2013-06-05 10:29:17 EDT
Created attachment 757236 [details]
File: ifcfg.log
Comment 6 Mark Hamzy 2013-06-05 10:29:20 EDT
Created attachment 757237 [details]
File: ks.cfg
Comment 7 Mark Hamzy 2013-06-05 10:29:24 EDT
Created attachment 757239 [details]
File: lsblk_output
Comment 8 Mark Hamzy 2013-06-05 10:29:28 EDT
Created attachment 757240 [details]
File: nmcli_dev_list
Comment 9 Mark Hamzy 2013-06-05 10:29:31 EDT
Created attachment 757241 [details]
File: packaging.log
Comment 10 Mark Hamzy 2013-06-05 10:29:35 EDT
Created attachment 757242 [details]
File: program.log
Comment 11 Mark Hamzy 2013-06-05 10:29:39 EDT
Created attachment 757243 [details]
File: storage.log
Comment 12 Mark Hamzy 2013-06-05 10:29:43 EDT
Created attachment 757244 [details]
File: syslog
Comment 13 Mark Hamzy 2013-06-05 10:34:29 EDT
Proposing as a FinalBlocker:

"The installer must be able to use all available kickstart delivery methods."
Comment 14 Adam Williamson 2013-06-05 12:34:08 EDT
Discussed at 2013-06-05 blocker review meeting: http://meetbot.fedoraproject.org/fedora-blocker-review/2013-06-05/f19final-blocker-review-3.2013-06-05-16.05.log.txt . We would like more details before making a call on this one. In particular, we noted that the config in question has multiple network interfaces attached to the same network, and wondered if this might be causing the issue (and if there's a valid reason for that configuration). If you could test in a few different configs and see if you can pin down the config which causes this to happen, that'd be great. We'll also be testing remote ks sources with Final TC1 to see if we can reproduce this.
Comment 15 Mark Hamzy 2013-06-05 13:47:27 EDT
This also fails with only one network interface defined.

boot: linux inst.vnc inst.sshd ip=9.5.114.36::9.5.114.1:255.255.255.0:sharpie.rch.stglabs.ibm.com:eth0:none nameserver=9.10.244.100 bootdev=eth0 ks=http://chukar.rch.stglabs.ibm.com/Fedora19-sharpie-lvm_auto-cdrom-minimal-ks.cfg

By the way, the two network interfaces on the same subnet has been how I have always tested/used Fedora 18 and Fedora 19 with.  This is a new failure.

I powered off the LPAR and switched into a configuration where only one network card was defined.  It also failed.

[anaconda root@sharpie /]# ip addr show
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN 
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast state UNKNOWN qlen 1000
    link/ether 2a:0f:41:b7:3f:03 brd ff:ff:ff:ff:ff:ff
    inet 9.5.114.36/24 brd 9.5.114.255 scope global eth0
       valid_lft forever preferred_lft forever

I don't know what other kind of config you want me to test with, but I will be happy to try whatever...
Comment 16 Adam Williamson 2013-06-05 14:50:44 EDT
Well I just tried a simple:

ks=http://www.happyassassin.net/ks/ordered_unattended.ks

with final TC1 DVD and that worked. So at least we haven't utterly broken http ks'es; this must be more specific in some way or other. Hard to make a blocker call until we know exactly what the trigger is. Static networking? Something specific in Mark's kickstart?
Comment 17 Mark Hamzy 2013-06-05 16:13:03 EDT
I tried with dhcp and no kickstart file:

boot: linux inst.vnc
...
Traceback (most recent call first):
  File "/usr/lib64/python2.7/site-packages/gi/types.py", line 113, in function
    return info.invoke(*args, **kwargs)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/nm.py", line 436, in _update_settings
    None)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/nm.py", line 414, in nm_update_settings_of_device
    return _update_settings(_device_settings(name), key1, key2, value, default_type_str)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/network.py", line 318, in dumpMissingDefaultIfcfgs
    nm.nm_update_settings_of_device(devname, 'connection', 'id', devname)
  File "/usr/lib64/python2.7/site-packages/pyanaconda/network.py", line 893, in networkInitialize
    if dumpMissingDefaultIfcfgs():
  File "/sbin/anaconda", line 1037, in <module>
    networkInitialize(ksdata)
GError: GDBus.Error:org.freedesktop.NetworkManager.Settings.NotPrivileged: Insufficient privileges.
...
Comment 18 Radek Vykydal 2013-06-06 05:20:16 EDT
Seems to be related to polkit crash as seen in syslog from comment #12

14:25:59,893 INFO dbus-daemon: dbus[1207]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service'
14:25:59,894 NOTICE dbus: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service'
14:25:59,894 WARNING systemd: Cannot add dependency job for unit lvm2-monitor.service, ignoring: Unit dm-event.socket failed to load: No such file or directory. See system logs and 'systemctl status dm-event.socket' for details.
14:25:59,898 INFO systemd: Starting Authorization Manager...
14:25:59,967 INFO polkitd: Started polkitd version 0.111
14:25:59,989 NOTICE systemd: polkit.service: main process exited, code=killed, status=11/SEGV
14:25:59,990 ERR systemd: Failed to start Authorization Manager.
14:25:59,990 NOTICE systemd: Unit polkit.service entered failed state.

So, proxima parada: polkit - any ideas, debugging hints (please see the log in comment #12)?
Comment 19 Miloslav Trmač 2013-06-06 13:10:41 EDT
During a non-kickstart installation of Fedora-19-TC1-x86_64-DVD , polkitd starts in the installation environment normally (the process is running and there are no SEGV entries in the generated logs.)

Mark, can you reproduce this on a non-ppc architecture?
Comment 20 Adam Williamson 2013-06-06 13:20:19 EDT
On an x86_64 install of Final TC1 from a kickstart (http://www.happyassassin.net/ks/ordered_unattended.ks ), I see no crash of polkit in anaconda's syslog: I see it starting successfully.

Mark, can you get any more details on the polkit crash in any way? Get to a console and look in journalctl perhaps?
Comment 21 Miloslav Trmač 2013-06-06 13:29:53 EDT
The mozjs17 testsuite on ppc crashes as well (#971519), which might be related.
Comment 22 Miloslav Trmač 2013-06-06 14:23:14 EDT
(In reply to Miloslav Trmač from comment #21)
> The mozjs17 testsuite on ppc crashes as well (#971519), which might be
> related.

Running polkitd in a f19 mock crashes with:
> #0  0x00003fffb79706e8 in js::gc::InitMemorySubsystem () at /usr/src/debug/mozjs17.0.0/js/src/gc/Memory.cpp:306
> #1  0x00003fffb771eee4 in JS_Init (maxbytes=<optimized out>) at /usr/src/debug/mozjs17.0.0/js/src/jsapi.cpp:1057
> #2  0x0000000050320298 in 000000a7.plt_call.polkit_subject_get_type ()
> #3  0x00003fffb7c96614 in .g_object_newv () from /lib64/libgobject-2.0.so.0
> #4  0x00003fffb7c96e70 in .g_object_new () from /lib64/libgobject-2.0.so.0
> #5  0x000000005031d898 in .polkit_backend_authority_get ()
> #6  0x000000005031b75c in .main ()

with #0 being
> 302	void
> 303	InitMemorySubsystem()
> 304	{
> 305	    if (size_t(sysconf(_SC_PAGESIZE)) != PageSize)
> 306	        MOZ_CRASH();
> 307	}
and
> (gdb) call sysconf(_SC_PAGESIZE)
> $2 = 65536
> (gdb) p PageSize
> $3 = 4096

I think that's a sufficient evidence for the causal relationship.
Comment 23 Mark Hamzy 2013-06-06 15:05:15 EDT
Miloslav,

I have not had any free time to try it on non-ppc architecture, sorry.

Adam,

[anaconda root@ip9-5-211-215 ~]# systemctl status
...
polkit.service - Authorization Manager
   Loaded: loaded (/usr/lib/systemd/system/polkit.service; static)
   Active: failed (Result: signal) since Wed 2013-06-05 20:01:25 UTC; 21h ago
     Docs: man:polkit(8)
  Process: 1268 ExecStart=/usr/lib/polkit-1/polkitd --no-debug (code=killed, signal=SEGV)

Jun 05 20:01:25 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Starting Authorization Manager...
Jun 05 20:01:25 ip9-5-211-215.rch.stglabs.ibm.com polkitd[1268]: Started polkitd version 0.111
Jun 05 20:01:25 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: polkit.service: main process exited, code=killed, status=11/SEGV
Jun 05 20:01:25 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Failed to start Authorization Manager.
Jun 05 20:01:25 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Unit polkit.service entered failed state.
[anaconda root@ip9-5-211-215 ~]# journalctl --unit=polkit.service
-- Logs begin at Wed 2013-06-05 19:57:11 UTC, end at Thu 2013-06-06 17:59:20 UTC. --
Jun 05 19:57:20 localhost systemd[1]: Starting Authorization Manager...
Jun 05 19:57:20 localhost polkitd[1073]: Started polkitd version 0.111
Jun 05 19:57:20 localhost systemd[1]: polkit.service: main process exited, code=killed, status=11/SEGV
Jun 05 19:57:20 localhost systemd[1]: Failed to start Authorization Manager.
Jun 05 19:57:20 localhost systemd[1]: Unit polkit.service entered failed state.
Jun 05 19:57:45 localhost systemd[1]: Starting Authorization Manager...
Jun 05 19:57:45 localhost polkitd[1082]: Started polkitd version 0.111
Jun 05 19:57:45 localhost systemd[1]: polkit.service: main process exited, code=killed, status=11/SEGV
Jun 05 19:57:45 localhost systemd[1]: Failed to start Authorization Manager.
Jun 05 19:57:45 localhost systemd[1]: Unit polkit.service entered failed state.
Jun 05 19:58:15 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Starting Authorization Manager...
Jun 05 19:58:15 ip9-5-211-215.rch.stglabs.ibm.com polkitd[1252]: Started polkitd version 0.111
Jun 05 19:58:15 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: polkit.service: main process exited, code=killed, status=11/SEGV
Jun 05 19:58:15 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Failed to start Authorization Manager.
Jun 05 19:58:15 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Unit polkit.service entered failed state.
Jun 05 20:01:00 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Starting Authorization Manager...
Jun 05 20:01:00 ip9-5-211-215.rch.stglabs.ibm.com polkitd[1257]: Started polkitd version 0.111
Jun 05 20:01:00 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: polkit.service: main process exited, code=killed, status=11/SEGV
Jun 05 20:01:00 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Failed to start Authorization Manager.
Jun 05 20:01:00 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Unit polkit.service entered failed state.
Jun 05 20:01:25 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Starting Authorization Manager...
Jun 05 20:01:25 ip9-5-211-215.rch.stglabs.ibm.com polkitd[1268]: Started polkitd version 0.111
Jun 05 20:01:25 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: polkit.service: main process exited, code=killed, status=11/SEGV
Jun 05 20:01:25 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Failed to start Authorization Manager.
Jun 05 20:01:25 ip9-5-211-215.rch.stglabs.ibm.com systemd[1]: Unit polkit.service entered failed state.
[anaconda root@ip9-5-211-215 tmp]# wget --quiet http://ppc.koji.fedoraproject.org/kojifiles/packages/mozjs17/17.0.0/4.fc19/ppc64/mozjs17-debuginfo-17.0.0-4.fc19.ppc64.rpm
[anaconda root@ip9-5-211-215 tmp]# wget --quiet http://ppc.koji.fedoraproject.org/kojifiles/packages/glib2/2.36.2/1.fc19/ppc64/glib2-debuginfo-2.36.2-1.fc19.ppc64.rpm
[anaconda root@ip9-5-211-215 tmp]# wget --quiet http://ppc.koji.fedoraproject.org/kojifiles/packages/polkit/0.111/2.fc19/ppc64/polkit-debuginfo-0.111-2.fc19.ppc64.rpm
[anaconda root@ip9-5-211-215 tmp]# rmdir /usr/lib/debug
[anaconda root@ip9-5-211-215 tmp]# mkdir /tmp/debuginfo
[anaconda root@ip9-5-211-215 tmp]# ln -s /tmp/debuginfo /usr/lib/debug
[anaconda root@ip9-5-211-215 tmp]# rpm -i mozjs17-debuginfo-17.0.0-4.fc19.ppc64.rpm glib2-debuginfo-2.36.2-1.fc19.ppc64.rpm polkit-debuginfo-0.111-2.fc19.ppc64.rpm
[anaconda root@ip9-5-211-215 tmp]# gdb /usr/lib/polkit-1/polkitd 
(gdb) run
Program received signal SIGSEGV, Segmentation fault.
0x00003fff8e2a06e8 in js::gc::InitMemorySubsystem () at /usr/src/debug/mozjs17.0.0/js/src/gc/Memory.cpp:306
306	        MOZ_CRASH();
(gdb) bt
#0  0x00003fff8e2a06e8 in js::gc::InitMemorySubsystem () at /usr/src/debug/mozjs17.0.0/js/src/gc/Memory.cpp:306
#1  0x00003fff8e04eee4 in JS_Init (maxbytes=<optimized out>) at /usr/src/debug/mozjs17.0.0/js/src/jsapi.cpp:1057
#2  0x0000000025d80298 in polkit_backend_js_authority_constructed (object=0x1000afc5040) at polkitbackendjsauthority.c:451
#3  0x00003fff8e5c6614 in g_object_newv (object_type=1099695878096, n_parameters=<optimized out>, parameters=<optimized out>)
    at gobject.c:1747
#4  0x00003fff8e5c6e70 in g_object_new (object_type=1099695878096, first_property_name=0x0) at gobject.c:1548
#5  0x0000000025d7d898 in polkit_backend_authority_get () at polkitbackendauthority.c:1374
#6  0x0000000025d7b75c in main (argc=1, argv=0x3fffddc40b98) at polkitd.c:217
Comment 24 Miloslav Trmač 2013-06-06 15:07:26 EDT
(In reply to Mark Hamzy from comment #23)
> /usr/src/debug/mozjs17.0.0/js/src/gc/Memory.cpp:306
> 306	        MOZ_CRASH();
Thank you, this confirms the root cause.

Patches that seem to fix it were attached to #971519; I'll keep this bug open only to verify that the installation works after mozjs17 is fixed.
Comment 25 Mark Hamzy 2013-06-06 15:08:26 EDT
Awesome work Miloslav!
Comment 26 Adam Williamson 2013-06-10 14:40:33 EDT
Discussed at 2013-06-10 blocker review meeting: http://meetbot.fedoraproject.org/fedora-blocker-review/2013-06-10/f19final-blocker-review-4.2013-06-10-16.01.log.txt . This is a showstopper bug but is specific to a non-blocking arch (PPC64); therefore by precedent and policy it's rejected as a blocker but accepted as a freeze exception issue.
Comment 27 Miloslav Trmač 2013-12-05 15:24:23 EST
Cleaning up old bugs - Mark, could you confirm that installation on PPC now works, please?
Comment 28 Mark Hamzy 2013-12-05 15:51:35 EST
I have not seen this in ages. Closing...

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