Description of problem: There are error messages in message.log after boot. Version-Release number of selected component (if applicable): How reproducible: Steps to Reproduce: 1. boot at runlevel 5 by default. 2. See message.log by Log Viewer 2.32.0 3. Actual results: Expected results: Additional info: I copy here all Network Manager messages from message.log. >>> Nov 12 20:15:55 lhost NetworkManager[1145]: <info> NetworkManager (version 0.8.1-10.git20100831.fc14) is starting... Nov 12 20:15:55 lhost NetworkManager[1145]: <info> Read config file /etc/NetworkManager/NetworkManager.conf Nov 12 20:15:55 lhost NetworkManager[1145]: <info> VPN: loaded org.freedesktop.NetworkManager.openconnect Nov 12 20:15:55 lhost NetworkManager[1145]: <info> VPN: loaded org.freedesktop.NetworkManager.openvpn Nov 12 20:15:55 lhost NetworkManager[1145]: <info> VPN: loaded org.freedesktop.NetworkManager.pptp Nov 12 20:15:55 lhost NetworkManager[1145]: <info> VPN: loaded org.freedesktop.NetworkManager.vpnc Nov 12 20:15:55 lhost NetworkManager[1145]: <info> trying to start the modem manager... <<< >>> Nov 12 20:15:56 lhost NetworkManager[1145]: <info> monitoring kernel firmware directory '/lib/firmware'. Nov 12 20:15:56 lhost NetworkManager[1145]: ifcfg-rh: Acquired D-Bus service com.redhat.ifcfgrh1 Nov 12 20:15:56 lhost NetworkManager[1145]: <info> Loaded plugin ifcfg-rh: (c) 2007 - 2008 Red Hat, Inc. To report bugs please use the NetworkManager mailing list. Nov 12 20:15:56 lhost NetworkManager[1145]: ifcfg-rh: parsing /etc/sysconfig/network-scripts/ifcfg-lo ... Nov 12 20:15:56 lhost NetworkManager[1145]: <info> WiFi enabled by radio killswitch; enabled by state file Nov 12 20:15:56 lhost NetworkManager[1145]: <info> WWAN enabled by radio killswitch; disabled by state file Nov 12 20:15:56 lhost NetworkManager[1145]: <info> WiMAX enabled by radio killswitch; enabled by state file Nov 12 20:15:56 lhost NetworkManager[1145]: <info> Networking is enabled by state file <<< >>> Nov 12 20:15:56 lhost NetworkManager[1145]: <info> (eth0): carrier is OFF Nov 12 20:15:56 lhost NetworkManager[1145]: <info> (eth0): new Ethernet device (driver: 'ATL1E' ifindex: 2) Nov 12 20:15:56 lhost NetworkManager[1145]: <info> (eth0): exported as /org/freedesktop/NetworkManager/Devices/0 Nov 12 20:15:56 lhost NetworkManager[1145]: <info> (eth0): now managed Nov 12 20:15:56 lhost NetworkManager[1145]: <info> (eth0): device state change: 1 -> 2 (reason 2) Nov 12 20:15:56 lhost NetworkManager[1145]: <info> (eth0): bringing up device. Nov 12 20:15:56 lhost NetworkManager[1145]: <info> (eth0): preparing device. Nov 12 20:15:56 lhost NetworkManager[1145]: <info> (eth0): deactivating device (reason: 2). Nov 12 20:15:56 lhost NetworkManager[1145]: <info> (eth0): carrier now ON (device state 2) Nov 12 20:15:56 lhost NetworkManager[1145]: <info> (eth0): device state change: 2 -> 3 (reason 40) Nov 12 20:15:56 lhost NetworkManager[1145]: <info> modem-manager is now available Nov 12 20:15:56 lhost NetworkManager[1145]: <warn> bluez error getting default adapter: The name org.bluez was not provided by any .service files Nov 12 20:15:56 lhost NetworkManager[1145]: <info> Trying to start the supplicant... <<< here error messages ... >>> Nov 12 20:16:05 lhost acpid: client connected from 1819[0:0] Nov 12 20:16:05 lhost acpid: 1 client rule loaded Nov 12 20:16:07 lhost NetworkManager[1145]: <error> [1289582167.783197] [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name Nov 12 20:16:07 lhost NetworkManager[1145]: <error> [1289582167.783858] [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name Nov 12 20:16:07 lhost NetworkManager[1145]: <error> [1289582167.784253] [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name Nov 12 20:16:10 lhost rtkit-daemon[1915]: Successfully made thread 1913 of process 1913 (/usr/bin/pulseaudio) owned by '42' high priority at nice level -11. Nov 12 20:16:11 lhost gdm-simple-greeter[1878]: Gtk-WARNING: gtkwidget.c:5691: widget not within a GtkWindow Nov 12 20:16:11 lhost rtkit-daemon[1915]: Successfully made thread 1930 of process 1913 (/usr/bin/pulseaudio) owned by '42' RT at priority 5. Nov 12 20:16:11 lhost gdm-simple-greeter[1878]: WARNING: Unable to load CK history: no seat-id found Nov 12 20:16:11 lhost rtkit-daemon[1915]: Successfully made thread 1933 of process 1913 (/usr/bin/pulseaudio) owned by '42' RT at priority 5. Nov 12 20:16:25 lhost gdm-simple-greeter[1878]: WARNING: Failed to send buffer Nov 12 20:16:26 lhost seahorse-agent[2028]: seahorse_agent_cache_init: assertion `GPG_IS_OK (err)' failed Nov 12 20:16:26 lhost kernel: [ 46.736644] fuse init (API version 7.14) Nov 12 20:16:26 lhost NetworkManager[1145]: <error> [1289582186.746607] [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name Nov 12 20:16:26 lhost NetworkManager[1145]: <error> [1289582186.747317] [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name Nov 12 20:16:26 lhost NetworkManager[1145]: <error> [1289582186.747629] [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name Nov 12 20:16:26 lhost NetworkManager[1145]: <error> [1289582186.747886] [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name Nov 12 20:16:26 lhost NetworkManager[1145]: <error> [1289582186.748135] [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no such name Nov 12 20:16:27 lhost rtkit-daemon[1915]: Successfully made thread 2073 of process 2073 (/usr/bin/pulseaudio) owned by '500' high priority at nice level -11. Nov 12 20:16:27 lhost pulseaudio[2073]: pid.c: Stale PID file, overwriting. <<< here I start internet connection by PPPoE. >>> Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) starting connection 'dsl' Nov 12 20:16:52 lhost NetworkManager[1145]: <info> (eth0): device state change: 3 -> 4 (reason 0) Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled... Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started... Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled... Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete. Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting... Nov 12 20:16:52 lhost NetworkManager[1145]: <info> (eth0): device state change: 4 -> 5 (reason 0) Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) successful. Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled. Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete. Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started... Nov 12 20:16:52 lhost NetworkManager[1145]: <info> (eth0): device state change: 5 -> 7 (reason 0) Nov 12 20:16:52 lhost NetworkManager[1145]: <info> starting PPP connection Nov 12 20:16:52 lhost NetworkManager[1145]: <info> pppd started with pid 2384 Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete. <<< Why it does want to open at /root/... ??? >>> Nov 12 20:16:52 lhost pppd[2384]: Warning: can't open options file /root/.ppprc: Permission denied <<< <<< Nov 12 20:16:52 lhost pppd[2384]: Plugin rp-pppoe.so loaded. Nov 12 20:16:52 lhost pppd[2384]: RP-PPPoE plugin version 3.8p compiled against pppd 2.4.5 Nov 12 20:16:52 lhost kernel: [ 72.538155] PPP generic driver version 2.4.2 Nov 12 20:16:52 lhost pppd[2384]: Plugin /usr/lib64/pppd/2.4.5/nm-pppd-plugin.so loaded. Nov 12 20:16:52 lhost pppd[2384]: pppd 2.4.5 started by root, uid 0 Nov 12 20:16:52 lhost pppd[2384]: PPP session is 23710 Nov 12 20:16:52 lhost kernel: [ 72.669615] NET: Registered protocol family 24 Nov 12 20:16:52 lhost pppd[2384]: Connected to 00:1e:f7:c7:25:1a via interface eth0 Nov 12 20:16:52 lhost pppd[2384]: Using interface ppp0 Nov 12 20:16:52 lhost pppd[2384]: Connect: ppp0 <--> eth0 Nov 12 20:16:52 lhost pppd[2384]: CHAP authentication succeeded Nov 12 20:16:52 lhost pppd[2384]: CHAP authentication succeeded Nov 12 20:16:52 lhost pppd[2384]: peer from calling number 00:1E:F7:C7:25:1A authorized Nov 12 20:16:52 lhost pppd[2384]: local IP address <> Nov 12 20:16:52 lhost pppd[2384]: remote IP address <> Nov 12 20:16:52 lhost pppd[2384]: primary DNS address <> Nov 12 20:16:52 lhost pppd[2384]: secondary DNS address <> Nov 12 20:16:52 lhost NetworkManager[1145]: <info> PPP manager(IP Config Get) reply received. Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) scheduled... Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) started... Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) scheduled... Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 4 of 5 (IP4 Configure Get) complete. Nov 12 20:16:52 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) started... Nov 12 20:16:53 lhost NetworkManager[1145]: <info> (eth0): device state change: 7 -> 8 (reason 0) Nov 12 20:16:53 lhost NetworkManager[1145]: <info> Policy set 'dsl' (ppp0) as default for IPv4 routing and DNS. Nov 12 20:16:53 lhost NetworkManager[1145]: <info> Updating /etc/hosts with new system hostname Nov 12 20:16:53 lhost NetworkManager[1145]: <info> Activation (eth0) successful, device activated. Nov 12 20:16:53 lhost NetworkManager[1145]: <info> Activation (eth0) Stage 5 of 5 (IP Configure Commit) complete. <<< here also error. Why Invalid? <<< Nov 12 20:16:53 lhost nm-dispatcher.action: nm_dispatcher_action: Invalid connection: '(null)' / 'connection setting not found' invalid: 1 <<<
(In reply to comment #0) > Description of problem: > There are error messages in message.log after boot. > Nov 12 20:16:07 lhost NetworkManager[1145]: <error> [1289582167.783197] > [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) > Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no > such name > Nov 12 20:16:07 lhost NetworkManager[1145]: <error> [1289582167.783858] > [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) > Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no > such name > Nov 12 20:16:07 lhost NetworkManager[1145]: <error> [1289582167.784253] > [nm-manager.c:1332] user_proxy_init(): could not init user settings proxy: (3) > Could not get owner of name 'org.freedesktop.NetworkManagerUserSettings': no > such name It should not appear as there is a test that the name has an owner before initializing proxy to user settings. However, I can reproduce the messages. They appear on logging on and out from gdm. (tested on Fedora 14 Live) Hmm, it needs more debugging. > <<< > > here I start internet connection by PPPoE. > > >>> > > Why it does want to open at /root/... ??? > >>> > Nov 12 20:16:52 lhost pppd[2384]: Warning: can't open options file > /root/.ppprc: Permission denied > <<< pppd reads its configuration file .ppprc in home directory (man pppd). pppd is run by NM as root, so it searches the file in /root. > <<< > > here also error. Why Invalid? > <<< > Nov 12 20:16:53 lhost nm-dispatcher.action: nm_dispatcher_action: Invalid > connection: '(null)' / 'connection setting not found' invalid: 1 > <<< The error is fixed upstream - bug 627649.
(In reply to comment #1) > > >>> > > Nov 12 20:16:52 lhost pppd[2384]: Warning: can't open options file > > /root/.ppprc: Permission denied > > <<< > > pppd reads its configuration file .ppprc in home directory (man pppd). > pppd is run by NM as root, so it searches the file in /root. > > I check: [root@lhost ~]# find / -mount -name .ppprc -print [root@lhost ~]# This file not found anywhere. This file /root/.ppprc not found also on my box. uname -r -> 2.6.35.6-48.fc14.x86_64
(In reply to comment #1) > here I start internet connection by PPPoE. > > > > >>> > > > > Why it does want to open at /root/... ??? > > >>> > > Nov 12 20:16:52 lhost pppd[2384]: Warning: can't open options file > > /root/.ppprc: Permission denied > > <<< > > pppd reads its configuration file .ppprc in home directory (man pppd). > pppd is run by NM as root, so it searches the file in /root. > man pppd: >>> OPTIONS FILES Options can be taken from files as well as the command line. Pppd reads options from the files /etc/ppp/options, ~/.ppprc and /etc/ppp/options.ttyname (in that order) before processing the options on the command line. <<< ls -al /etc/ppp >>> @lhost ~]$ ls -al /etc/ppp total 84 drwxr-xr-x. 3 root root 4096 Nov 18 22:13 . drwxr-xr-x. 127 root root 12288 Nov 19 20:18 .. -rw-------. 1 root root 232 Oct 23 09:53 chap-secrets -rw-------. 1 root root 349 Nov 16 12:25 eaptls-client -rw-------. 1 root root 405 Nov 16 12:25 eaptls-server -rw-r--r--. 1 root root 2276 Sep 9 2009 firewall-masq -rw-r--r--. 1 root root 978 Sep 9 2009 firewall-standalone -rwxr-xr-x. 1 root root 386 Sep 27 23:45 ip-down -rwxr-xr-x. 1 root root 3262 Sep 27 23:45 ip-down.ipv6to4 -rwxr-xr-x. 1 root root 430 Sep 27 23:45 ip-up -rwxr-xr-x. 1 root root 6481 Sep 27 23:45 ip-up.ipv6to4 -rwxr-xr-x. 1 root root 1687 Sep 27 23:45 ipv6-down -rwxr-xr-x. 1 root root 3200 Sep 27 23:45 ipv6-up -rw-r--r--. 1 root root 5 Nov 16 12:25 options ------ >>> ------- >>> -------- >>> ******** -rw-r--r--. 1 root root 1759 Jun 16 19:06 options.pptp ------ >>> ------- >>> -------- >>> ******** -rw-------. 1 root root 231 Oct 23 09:53 pap-secrets drwxr-xr-x. 2 root root 4096 Sep 27 23:58 peers -rw-r--r--. 1 root root 104 Sep 9 2009 pppoe-server-options [@lhost ~]$ cat /etc/ppp/options lock [@lhost ~]$ <<< There is the file '/etc/ppp/options'. May be this will be enough by 'man pppd'. Or pppd looks for '/etc/ppp/options.ppp'? Is it right the attempt access to ' ~/.ppprc' (in my case '/root/.ppprc'), when there is the file '/etc/ppp/options'?
The referenced bug should be long-since fixed in F13 & F14 updates.