Failure to login on first attemp

[andrew harland]

I've recently started having a problem logging in FC16 x64: -

On first attempt, end up in loop (can see 'Loading initial ramdisk' for a second time) and then nothing just a blank screen, sometimes Ctrl+Atl+Backspace can break the loop but it's not consistent.

If I wait roughly a minute or so, I see the second 'Loading initial ramdisk', login prompt appears and I can log in no problems.

This has only started happening recently, I'm currently on kernel 3.4.2-1.fc16.x86_64.

I have tried to find a solution, there are a couple of posts (couldn't add URL's, post was denied) but neither of these seem to fit.

I'm no Linux expert, as such I haven't messed around with any settings/policies, simply use yum update; and don't know where to start.

I have got this from the messages log but it may as well be written in DoubleDutch

Jun 26 20:31:21 localhost NetworkManager[1189]: <info> (p32p1): IP6 addrconf timed out or failed.
Jun 26 20:31:21 localhost NetworkManager[1189]: <info> Activation (p32p1) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Jun 26 20:31:21 localhost NetworkManager[1189]: <info> Activation (p32p1) Stage 4 of 5 (IPv6 Configure Timeout) started...
Jun 26 20:31:21 localhost NetworkManager[1189]: <info> Activation (p32p1) Stage 4 of 5 (IPv6 Configure Timeout) complete.
Jun 26 20:31:23 localhost dbus[1235]: [system] Failed to activate service 'org.freedesktop.ColorManager': timed out
Jun 26 20:31:23 localhost dbus-daemon[1235]: dbus[1235]: [system] Failed to activate service 'org.freedesktop.ColorManager': timed out
Jun 26 20:31:23 localhost dbus[1235]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Jun 26 20:31:23 localhost dbus-daemon[1235]: dbus[1235]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Jun 26 20:31:23 localhost dbus-daemon[1235]: process 1235: arguments to dbus_message_set_reply_serial() were incorrect, assertion "reply_serial != 0" failed in file dbus-message.c line 1009.
Jun 26 20:31:23 localhost dbus-daemon[1235]: This is normally a bug in some application using the D-Bus library.
Jun 26 20:31:23 localhost dbus-daemon[1235]: D-Bus not built with -rdynamic so unable to print a backtrace
Jun 26 20:31:23 localhost avahi-daemon[1212]: Disconnected from D-Bus, exiting.
Jun 26 20:31:23 localhost avahi-daemon[1212]: Got SIGTERM, quitting.
Jun 26 20:31:23 localhost NetworkManager[1189]: g_dbus_connection_real_closed: Remote peer vanished with error: Underlying GIOStream returned 0 bytes on an async read (g-io-error-quark, 0). Exiting.
Jun 26 20:31:23 localhost avahi-daemon[1212]: Leaving mDNS multicast group on interface virbr0.IPv4 with address 192.168.122.1.
Jun 26 20:31:23 localhost NetworkManager[1189]: <warn> disconnected by the system bus.
Jun 26 20:31:23 localhost avahi-daemon[1212]: Leaving mDNS multicast group on interface p32p1.IPv4 with address 192.168.0.5.
Jun 26 20:31:23 localhost systemd[1]: systemd-logind.service: main process exited, code=exited, status=1
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Demoting known real-time threads.
Jun 26 20:31:23 localhost dbus-daemon[1235]: g_dbus_connection_real_closed: Remote peer vanished with error: Underlying GIOStream returned 0 bytes on an async read (g-io-error-quark, 0). Exiting.
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Successfully demoted thread 2056 of process 2049 (/usr/bin/pulseaudio).
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Successfully demoted thread 2055 of process 2049 (/usr/bin/pulseaudio).
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Successfully demoted thread 2054 of process 2049 (/usr/bin/pulseaudio).
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Successfully demoted thread 2049 of process 2049 (/usr/bin/pulseaudio).
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Successfully demoted thread 1846 of process 1838 (/usr/bin/pulseaudio).
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Successfully demoted thread 1845 of process 1838 (/usr/bin/pulseaudio).
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Successfully demoted thread 1844 of process 1838 (/usr/bin/pulseaudio).
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Successfully demoted thread 1843 of process 1838 (/usr/bin/pulseaudio).
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Successfully demoted thread 1838 of process 1838 (/usr/bin/pulseaudio).
Jun 26 20:31:23 localhost rtkit-daemon[1839]: Demoted 9 threads.
Jun 26 20:31:23 localhost systemd[1]: Unit systemd-logind.service entered failed state.
Jun 26 20:31:23 localhost systemd[1]: dbus.service: main process exited, code=killed, status=6
Jun 26 20:31:23 localhost avahi-daemon[1212]: avahi-daemon 0.6.30 exiting.
Jun 26 20:31:23 localhost systemd[1]: accounts-daemon.service: main process exited, code=exited, status=1
Jun 26 20:31:23 localhost systemd[1]: Unit accounts-daemon.service entered failed state.
Jun 26 20:31:23 localhost systemd[1]: Unit dbus.service entered failed state.
Jun 26 20:31:23 localhost gnome-session[1873]: Gdk-WARNING: gnome-session: Fatal IO error 11 (Resource temporarily unavailable) on X server :0.#012
Jun 26 20:31:24 localhost pulseaudio[2049]: module-console-kit.c: Unable to subscribe to ConsoleKit signals: org.freedesktop.DBus.Error.Disconnected: Connection is closed
Jun 26 20:31:24 localhost pulseaudio[2049]: module.c: Failed to load module "module-console-kit" (argument: ""): initialization failed.
Jun 26 20:31:24 localhost pulseaudio[2049]: main.c: Module load failed.
Jun 26 20:31:24 localhost pulseaudio[2049]: main.c: Failed to initialize daemon.
Jun 26 20:31:24 localhost dbus-daemon[2104]: dbus[2104]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Jun 26 20:31:24 localhost dbus[2104]: [system] Activating via systemd: service name='org.freedesktop.Avahi' unit='dbus-org.freedesktop.Avahi.service'
Jun 26 20:31:24 localhost avahi-daemon[2108]: Found user 'avahi' (UID 70) and group 'avahi' (GID 70).
Jun 26 20:31:24 localhost avahi-daemon[2108]: Successfully dropped root privileges.
Jun 26 20:31:24 localhost avahi-daemon[2108]: avahi-daemon 0.6.30 starting up.
Jun 26 20:31:24 localhost dbus[2104]: [system] Successfully activated service 'org.freedesktop.Avahi'

Any help appreciated.

[tashirosgt]

Do the various log files of the form /var/log/boot*.log all show the same sequence of events? Or do some of them indicated a failed boot? Do you have any core dump directories in the /var/cache/abrt directory whose dates and times correspond to the failed attempt to boot? (If you're seeing 'Loading initial ramdisk' twice, I think this means the system crashed and rebooted.)

How old is your hardware?

[andrew harland]

Nothing exceptional in the log files.

boot.log

messages.tar.gz

Nothing in abrt.

This evening I have stopped TCSD & ISCI services from starting as I don't think I need these, and other posts were suggesting these could be a problem, but to no effect.

How can I tell if it is actually rebooting; I don't get the grub menu or anything to suggest this is what is happening. I'm not saying you're wrong, but if it were rebooting wouldn't I simply get stuck in a loop. As it is if I leave things alone after the second message I can log in fine.

Put the machine together myself, less than a year ago; apart from a few niggles that I've managed to sort out, Fedora 15/16 have run fine.

BTW, I do have VBox installed and Virtual Machine Manager, but again I've had these installed for a while with no issues.

[tashirosgt]

The /var/log/boot.log will be from the most recent boot, so it would show a successful boot. Another one of the boot logs in /var/log might show a failure.

My thought about your rebooting is merely based on the fact that "Loading initial ramdisk" is a done very early in the boot process. I suppose the fact that the message appears twice might just be a video effect where the same screen is shown twice.

The lines in /var/log/messages that have "imklog" in them are near beginning of new boot. I see you have:

Jun 28 18:08:18 localhost kernel: imklog 5.8.10, log source = /proc/kmsg started.

and

Jun 28 18:10:46 localhost kernel: imklog 5.8.10, log source = /proc/kmsg started.

i don't know if this shows the problem happening or whether you rebooted the machine manually. It helps to find things in the log if you can observe the times the problem happens (if possible to the nearest second) on a clock synchronized with the machine's clock.

[andrew harland]

Hi,
The boot.log was from a fresh boot, I had done

logrotate --force /etc/logrotate.conf

so I'm hoping that this would only contain information relating to that boot.

I didn't reboot the machine, this is the output from waiting, about a minute or so, at the login screen.

I take your point that the imklog lines in the boot.log, does look like it has rebooted. I'm just confused as to why the second time, logging in is successful; I'd expect, everything being equal, that rebooting would clear the slate and I'd be in a situation whereby I couldn't log in.

[tashirosgt]

Look at what happens in the lines before the ones with imklog. If you can identify which imklog line is the succesful boot, the lines before it may tell you why the previous boot was aborted. I don't think the error messages about bluez service mean much because I get them in my logs. The Gtk error might be meaningful, but we'll have to research it.

A shot-in-the-dark line of thinking is that something about a normal shutdown could incorrectly save a file that tells what should be done on the next boot. The next boot reads the bad file and shuts down. When it shuts down it saves a different file, perhaps a default or blank one, which works when the machine reboots. However, I don't have a good grasp of what files this could be.

I think the logs of the form /var/log/gdm/0:greeter-log* refer to the login screen. Mine have a lot of debug messages in them and end with a

(gnome-settings-daemon:1194): GLib-GObject-CRITICAL **: g_object_unref: assertion `G_IS_OBJECT (object)' failed

However, I have no problems with logins. Do all your greeter-logs look the same?

[andrew harland]

I've attached the greeter logs.

:0-greeter.log

:1-greeter.log

You can see at line 114, the difference - Not sure what to make of it.

There does seem to be a lot of issues around gdm, pam etc.

[tashirosgt]

I suppose we are dealing with software that has threads, so it doesn't execute in a completely predicable manner. Thus the logs wouldn't match line-by-line. What I notice about the logs is that the 0-greeter... log doesn't show a shutdown process ( it doesn't a line like " GsmManager: starting phase EXIT". I don't claim to be good at interpreting those messages, but I don't see any obvious sign of what caused a reboot (assuming the 0-greeter log is from such a case and not simply the current log on a machine that hasn't been shutdown yet).

Returning to the messages log, the "imklog...." line at 217 (if I haven't inadvertently introducted some linefeeds while fooling with the file) seems to be preceeded by a shutdown process. The "imklog..." line at 1698 isn't. The messages above it like:

Jun 28 18:09:08 localhost gdm-binary[1515]: WARNING: GdmDisplay: display lasted 0.018430 seconds
Jun 28 18:09:08 localhost gdm-binary[1515]: WARNING: GdmLocalDisplayFactory: maximum number of X display failures reached: check X server log for errors

suggest that you check the /var/log/Xorg.*.log files. I don't know how easy it will be to figure out which ones correspond to the delayed login situation. ( On my FC 17 machine, I don't see any warnings like the above in the /var/log/messages files.)

Many problems are caused by video drivers. Instead of diagnosis (which is not always possible) there is always the "replace random parts" approach. In computer this means re-installing modules or replacing them with alternatives. At least attempting diagnosis keeps the thread current without overtly bumping it.

[andrew harland]

Hi,
I'd read some posts suggesting it might have something to do with the graphics, so I tried installing the proprietary driver and got myself into a right mess; couldn't boot properly at all.

So I've circumvented the whole problem and installed 17, which at the moment is working great.

Thanks for your time.

[fonya]

I've got the same problem, at the morning everything working right, I installed Acrobat Read from adobe.com /i486 rpm/, with yum localinstall, and the next boot, I need login twice at gdm only, and the networkmanager applet not started, only if I restarted the NetworkManage "service".
I removed the newly installed packages (atk-2.2.0-2.fc16.i686 avahi-libs-0.6.30-4.fc16.i686 libXcomposite-0.4.3-2.fc15.i686 jasper-libs-1.900.1-18.fc16.i686 gdk-pixbuf2-2.24.1-1.fc16.i686 libidn-1.22-3.fc16.i686 audit-libs-2.2.1-1.fc16.i686 cups-libs-1.5.2-9.fc16.i686 gtk2-2.24.8-3.fc16.i686 libXt-1.1.1-1.fc16.i686 AdobeReader_enu-9.5.1-1.i486)
And this is the new, I have never seen this before:

Sep 12 15:48:05 cellaxps dbus[1156]: [system] Failed to activate service 'org.freedesktop.ColorManager': timed out
Sep 12 15:48:05 cellaxps dbus-daemon[1156]: dbus[1156]: [system] Failed to activate service 'org.freedesktop.ColorManager': timed out
Sep 12 15:48:05 cellaxps dbus[1156]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Sep 12 15:48:05 cellaxps dbus-daemon[1156]: dbus[1156]: [system] Failed to activate service 'org.freedesktop.systemd1': timed out
Sep 12 15:48:05 cellaxps dbus-daemon[1156]: process 1156: arguments to dbus_message_set_reply_serial() were incorrect, assertion "reply_serial != 0" failed in file dbus-message.c line 1009.
Sep 12 15:48:05 cellaxps dbus-daemon[1156]: This is normally a bug in some application using the D-Bus library.
Sep 12 15:48:05 cellaxps dbus-daemon[1156]: D-Bus not built with -rdynamic so unable to print a backtrace
...
Sep 12 15:48:30 cellaxps gdm-simple-slave[1951]: GLib-GObject-WARNING: invalid (NULL) pointer instance
Sep 12 15:48:30 cellaxps gdm-simple-slave[1951]: GLib-GObject-CRITICAL: g_signal_connect_data: assertion `G_TYPE_CHECK_INSTANCE (instance)' failed
Sep 12 15:48:30 cellaxps gdm-simple-slave[1951]: WARNING: Failed to create display proxy /org/gnome/DisplayManager/Display2: Could not get owner of name 'org.gnome.DisplayManager': no such name
Sep 12 15:48:30 cellaxps kernel: [   64.032357] composite sync not supported
Sep 12 15:48:30 cellaxps kernel: [   64.300181] composite sync not supported
Sep 12 15:48:31 cellaxps gdm[1957]: ******************* START **********************************
Sep 12 15:48:31 cellaxps gdm[1957]: [Thread debugging using libthread_db enabled]
Sep 12 15:48:31 cellaxps gdm[1957]: Using host libthread_db library "/lib64/libthread_db.so.1".
Sep 12 15:48:31 cellaxps gdm[1957]: [New Thread 0x7f75006aa700 (LWP 1954)]
Sep 12 15:48:31 cellaxps gdm[1957]: 0x000000308540f0dd in waitpid () from /lib64/libpthread.so.0

Any suggestion, what can I do whit this?

[andrew harland]

Sorry, never did get to the bottom of the problem and I spent several days trying to find a solution.

As I said, in the end I gave up and re-installed.

If you do find an answer, please post it just in case it happens again.

Thanks,
Andrew

[fonya]

Hi, I found the right answer in this forum. (I'm very frustrate, because I re-installed the system too, I'm using 2, or more weeks, and get back the twice login, and now disappeared the nm-applet too, after installing newest acrobat reader with yum).
So, the solution right now to me, the colord downgrade colord!? #$%$%# So I only need to work again the suspend/hybernate system, and I got back the FC14 functionality