|
Hi, I'm having problems with a 3G USB Modem where upon disconnect (e.g. due to lost signal) NetworkManager puts the device firstly from activated to failed (device state change: activated -> failed (reason 'ip-config-unavailable') [100 120 5]) and then from failed to unavailable. Really upon modem hangup from PPPD it should be transitioning to disconnected, allowing the user to reconnect if desired. Instead at the moment the user needs to Please can you advise on the best approach for me to take - I'm happy to have a go at fixing myself but haven't quite worked out where the state model lives within the code, equally if it's simpler for someone to fix straight away then that would be great too. Grateful for any advice - debug logs below. Thanks, Tristan Aug 22 18:54:33 hostname-1 kernel: [ 2186.884959] usb 2-1.3: new high-speed USB device number 7 using ehci_hcd Aug 22 18:54:34 hostname-1 mtp-probe: checking bus 2, device 7: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3" Aug 22 18:54:34 hostname-1 mtp-probe: bus: 2, device: 7 was not an MTP device Aug 22 18:54:34 hostname-1 kernel: [ 2186.992680] scsi21 : usb-storage 2-1.3:1.0 Aug 22 18:54:34 hostname-1 kernel: [ 2186.993136] scsi22 : usb-storage 2-1.3:1.1 Aug 22 18:54:35 hostname-1 kernel: [ 2187.995557] scsi 21:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2 Aug 22 18:54:35 hostname-1 kernel: [ 2187.996471] scsi 22:0:0:0: Direct-Access HUAWEI MMC Storage 2.31 PQ: 0 ANSI: 2 Aug 22 18:54:35 hostname-1 kernel: [ 2188.010530] sr1: scsi-1 drive Aug 22 18:54:35 hostname-1 kernel: [ 2188.010808] sr 21:0:0:0: Attached scsi CD-ROM sr1 Aug 22 18:54:35 hostname-1 kernel: [ 2188.012328] sr 21:0:0:0: Attached scsi generic sg2 type 5 Aug 22 18:54:35 hostname-1 kernel: [ 2188.013155] sd 22:0:0:0: Attached scsi generic sg3 type 0 Aug 22 18:54:35 hostname-1 kernel: [ 2188.024224] sd 22:0:0:0: [sdb] Attached SCSI removable disk Aug 22 18:54:35 hostname-1 usb_modeswitch: switching device 12d1:1446 on 002/007 Aug 22 18:54:35 hostname-1 kernel: [ 2188.087641] usb 2-1.3: USB disconnect, device number 7 Aug 22 18:54:35 hostname-1 kernel: [ 2188.089563] scsi 22:0:0:0: killing request Aug 22 18:54:41 hostname-1 kernel: [ 2194.551766] usb 2-1.3: new high-speed USB device number 8 using ehci_hcd Aug 22 18:54:41 hostname-1 mtp-probe: checking bus 2, device 8: "/sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3" Aug 22 18:54:41 hostname-1 kernel: [ 2194.659655] option 2-1.3:1.0: GSM modem (1-port) converter detected Aug 22 18:54:41 hostname-1 kernel: [ 2194.659837] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB0 Aug 22 18:54:41 hostname-1 kernel: [ 2194.660067] option 2-1.3:1.1: GSM modem (1-port) converter detected Aug 22 18:54:41 hostname-1 kernel: [ 2194.660382] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB1 Aug 22 18:54:41 hostname-1 kernel: [ 2194.660594] option 2-1.3:1.2: GSM modem (1-port) converter detected Aug 22 18:54:41 hostname-1 kernel: [ 2194.660725] usb 2-1.3: GSM modem (1-port) converter now attached to ttyUSB2 Aug 22 18:54:41 hostname-1 kernel: [ 2194.661449] scsi26 : usb-storage 2-1.3:1.3 Aug 22 18:54:41 hostname-1 kernel: [ 2194.662427] scsi27 : usb-storage 2-1.3:1.4 Aug 22 18:54:41 hostname-1 mtp-probe: bus: 2, device: 8 was not an MTP device Aug 22 18:54:41 hostname-1 modem-manager[5990]: <info> (ttyUSB0) opening serial port... Aug 22 18:54:42 hostname-1 usb_modeswitch: switched to 12d1:1001 on 002/007 Aug 22 18:54:42 hostname-1 modem-manager[5990]: <info> (ttyUSB0) closing serial port... Aug 22 18:54:42 hostname-1 modem-manager[5990]: <info> (ttyUSB0) serial port closed Aug 22 18:54:42 hostname-1 modem-manager[5990]: <info> (ttyUSB0) opening serial port... Aug 22 18:54:42 hostname-1 modem-manager[5990]: <info> (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3 claimed port ttyUSB0 Aug 22 18:54:42 hostname-1 kernel: [ 2195.661220] scsi 26:0:0:0: CD-ROM HUAWEI Mass Storage 2.31 PQ: 0 ANSI: 2 Aug 22 18:54:42 hostname-1 kernel: [ 2195.663296] scsi 27:0:0:0: Direct-Access HUAWEI MMC Storage 2.31 PQ: 0 ANSI: 2 Aug 22 18:54:42 hostname-1 kernel: [ 2195.673225] sr1: scsi-1 drive Aug 22 18:54:42 hostname-1 kernel: [ 2195.673459] sr 26:0:0:0: Attached scsi CD-ROM sr1 Aug 22 18:54:42 hostname-1 kernel: [ 2195.674190] sr 26:0:0:0: Attached scsi generic sg2 type 5 Aug 22 18:54:42 hostname-1 kernel: [ 2195.674735] sd 27:0:0:0: Attached scsi generic sg3 type 0 Aug 22 18:54:42 hostname-1 kernel: [ 2195.684014] sd 27:0:0:0: [sdb] Attached SCSI removable disk Aug 22 18:54:43 hostname-1 usb_modeswitch[7535]: usb_modeswitch: switched to 12d1:1001 on 2/8 Aug 22 18:54:44 hostname-1 modem-manager[5990]: <info> (ttyUSB0) closing serial port... Aug 22 18:54:44 hostname-1 modem-manager[5990]: <info> (ttyUSB0) serial port closed Aug 22 18:54:44 hostname-1 modem-manager[5990]: <info> (ttyUSB1) opening serial port... Aug 22 18:54:44 hostname-1 modem-manager[5990]: <info> (ttyUSB2) opening serial port... Aug 22 18:54:46 hostname-1 modem-manager[5990]: <info> (ttyUSB2) closing serial port... Aug 22 18:54:46 hostname-1 modem-manager[5990]: <info> (ttyUSB2) serial port closed Aug 22 18:54:46 hostname-1 modem-manager[5990]: <info> (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3 claimed port ttyUSB2 Aug 22 18:54:51 hostname-1 modem-manager[5990]: <info> (ttyUSB1) closing serial port... Aug 22 18:54:51 hostname-1 modem-manager[5990]: <info> (ttyUSB1) serial port closed Aug 22 18:54:51 hostname-1 modem-manager[5990]: <info> (Huawei): GSM modem /sys/devices/pci0000:00/0000:00:1d.0/usb2/2-1/2-1.3 claimed port ttyUSB1 Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <warn> (ttyUSB0): failed to look up interface index Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <debug> [1345658091.982782] [NetworkManagerUtils.c:869] nm_utils_get_proc_sys_net_value(): (ttyUSB0): error reading /proc/sys/net/ipv6/conf/ttyUSB0/accept_ra: (4) Failed to open file '/proc/sys/net/ipv6/conf/ttyUSB0/accept_ra': No such file or directory Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <debug> [1345658091.982844] [NetworkManagerUtils.c:869] nm_utils_get_proc_sys_net_value(): (ttyUSB0): error reading /proc/sys/net/ipv6/conf/ttyUSB0/use_tempaddr: (4) Failed to open file '/proc/sys/net/ipv6/conf/ttyUSB0/use_tempaddr': No such file or directory Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <info> WWAN now disabled by management service Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <debug> [1345658091.983015] [nm-manager.c:1490] manager_rfkill_update_one_type(): WWAN hw-enabled 1 sw-enabled 1 daemon-enabled 0 Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <debug> [1345658091.983041] [nm-manager.c:1345] manager_update_radio_enabled(): (ttyUSB0): setting radio disabled Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): new GSM/UMTS device (driver: 'option1' ifindex: 0) Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): exported as /org/freedesktop/NetworkManager/Devices/3 Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): now managed Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2] Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): deactivating device (reason 'managed') [2] Aug 22 18:54:51 hostname-1 NetworkManager[6336]: nm_system_iface_flush_routes: assertion `ifindex > 0' failed Aug 22 18:54:51 hostname-1 NetworkManager[6336]: nm_system_iface_flush_addresses: assertion `ifindex > 0' failed Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <debug> [1345658091.990754] [nm-device.c:4332] nm_device_state_changed(): (ttyUSB0): device is available, will transition to DISCONNECTED Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <debug> [1345658091.990793] [nm-device.c:4406] nm_device_queue_state(): (ttyUSB0): queued state change to disconnected (id 142) Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <debug> [1345658091.990877] [nm-manager.c:1149] system_create_virtual_devices(): creating virtual devices... Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <debug> [1345658091.991508] [nm-device.c:4374] queued_set_state(): (ttyUSB0): running queued state change to disconnected (id 142) Aug 22 18:54:51 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): device state change: unavailable -> disconnected (reason 'none') [20 30 0] Aug 22 18:55:26 hostname-1 NetworkManager[6336]: <debug> [1345658126.552917] [nm-agent-manager.c:298] impl_agent_manager_register(): (:1.108/org.freedesktop.nm-applet/1000) requesting permissions Aug 22 18:55:26 hostname-1 NetworkManager[6336]: <debug> [1345658126.564229] [nm-agent-manager.c:228] agent_register_permissions_done(): (:1.108/org.freedesktop.nm-applet/1000) agent registered Aug 22 18:55:40 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) starting connection '3 Internet' Aug 22 18:55:40 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): device state change: disconnected -> prepare (reason 'none') [30 40 0] Aug 22 18:55:40 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) scheduled... Aug 22 18:55:40 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) started... Aug 22 18:55:40 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 1 of 5 (Device Prepare) complete. Aug 22 18:55:40 hostname-1 modem-manager[5990]: <info> (ttyUSB0) opening serial port... Aug 22 18:55:40 hostname-1 modem-manager[5990]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (disabled -> enabling) Aug 22 18:55:40 hostname-1 modem-manager[5990]: <info> (ttyUSB2) opening serial port... Aug 22 18:55:40 hostname-1 modem-manager[5990]: <info> (ttyUSB0): using text mode for SMS Aug 22 18:55:40 hostname-1 modem-manager[5990]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabling -> enabled) Aug 22 18:55:40 hostname-1 NetworkManager[6336]: <info> WWAN now enabled by management service Aug 22 18:55:40 hostname-1 NetworkManager[6336]: <debug> [1345658140.774839] [nm-manager.c:1490] manager_rfkill_update_one_type(): WWAN hw-enabled 1 sw-enabled 1 daemon-enabled 1 Aug 22 18:55:40 hostname-1 NetworkManager[6336]: <debug> [1345658140.774883] [nm-manager.c:1345] manager_update_radio_enabled(): (ttyUSB0): setting radio enabled Aug 22 18:55:40 hostname-1 modem-manager[5990]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (enabled -> registered) Aug 22 18:55:41 hostname-1 modem-manager[5990]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (registered -> connecting) Aug 22 18:55:41 hostname-1 modem-manager[5990]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (connecting -> connected) Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) scheduled... Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) starting... Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): device state change: prepare -> config (reason 'none') [40 50 0] Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) successful. Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <debug> [1345658141.28099] [nm-device.c:2352] nm_device_activate_schedule_stage3_ip_config_start(): Activation (ttyUSB0) setting firewall zone 'default' Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <debug> [1345658141.28120] [nm-firewall-manager.c:107] nm_firewall_manager_add_or_change_zone(): (ttyUSB0) firewall zone add/change skipped (not running) Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) scheduled. Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 2 of 5 (Device Configure) complete. Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) started... Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): device state change: config -> ip-config (reason 'none') [50 70 0] Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> starting PPP connection Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <debug> [1345658141.28740] [nm-ppp-manager.c:1018] nm_ppp_manager_start(): command line: /usr/sbin/pppd nodetach lock nodefaultroute debug ttyUSB0 noipdefault noauth usepeerdns lcp-echo-failure 5 lcp-echo-interval 30 ipparam /org/freedesktop/NetworkManager/PPP/1 plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> pppd started with pid 7678 Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled... Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 3 of 5 (IP Configure Start) complete. Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) started... Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 4 of 5 (IPv6 Configure Timeout) complete. Aug 22 18:55:41 hostname-1 pppd[7678]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded. Aug 22 18:55:41 hostname-1 pppd[7678]: pppd 2.4.5 started by root, uid 0 Aug 22 18:55:41 hostname-1 pppd[7678]: Removed stale lock on ttyUSB0 (pid 6367) Aug 22 18:55:41 hostname-1 pppd[7678]: using channel 8 Aug 22 18:55:41 hostname-1 pppd[7678]: Using interface ppp0 Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <debug> [1345658141.49005] [nm-netlink-monitor.c:163] link_msg_handler(): netlink link message: iface idx 9 flags 0x1090 Aug 22 18:55:41 hostname-1 pppd[7678]: Connect: ppp0 <--> /dev/ttyUSB0 Aug 22 18:55:41 hostname-1 pppd[7678]: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x261168d6> <pcomp> <accomp>] Aug 22 18:55:41 hostname-1 NetworkManager[6336]: SCPlugin-Ifupdown: devices added (path: /sys/devices/virtual/net/ppp0, iface: ppp0) Aug 22 18:55:41 hostname-1 NetworkManager[6336]: SCPlugin-Ifupdown: device added (path: /sys/devices/virtual/net/ppp0, iface: ppp0): no ifupdown configuration found. Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <debug> [1345658141.49808] [nm-udev-manager.c:476] handle_uevent(): UDEV event: action 'add' subsys 'net' device 'ppp0' Aug 22 18:55:41 hostname-1 NetworkManager[6336]: <debug> [1345658141.49844] [nm-udev-manager.c:357] net_add(): (ppp0): ignoring interface with type 512 Aug 22 18:55:41 hostname-1 pppd[7678]: rcvd [LCP ConfReq id=0x0 <mru 1440> <asyncmap 0x0> <auth chap MD5> <magic 0xe3b6f0> <pcomp> <accomp>] Aug 22 18:55:41 hostname-1 pppd[7678]: sent [LCP ConfAck id=0x0 <mru 1440> <asyncmap 0x0> <auth chap MD5> <magic 0xe3b6f0> <pcomp> <accomp>] Aug 22 18:55:41 hostname-1 pppd[7678]: rcvd [LCP ConfNak id=0x1 <mru 1440>] Aug 22 18:55:41 hostname-1 pppd[7678]: sent [LCP ConfReq id=0x2 <mru 1440> <asyncmap 0x0> <magic 0x261168d6> <pcomp> <accomp>] Aug 22 18:55:41 hostname-1 pppd[7678]: rcvd [LCP ConfAck id=0x2 <mru 1440> <asyncmap 0x0> <magic 0x261168d6> <pcomp> <accomp>] Aug 22 18:55:41 hostname-1 pppd[7678]: sent [LCP EchoReq id=0x0 magic=0x261168d6] Aug 22 18:55:41 hostname-1 pppd[7678]: rcvd [LCP DiscReq id=0x1 magic=0xe3b6f0] Aug 22 18:55:41 hostname-1 pppd[7678]: rcvd [CHAP Challenge id=0x1 <86a5c3659c34a80fcaf515ecdc19bc95>, name = "UMTS_CHAP_SRVR"] Aug 22 18:55:41 hostname-1 pppd[7678]: sent [CHAP Response id=0x1 <f8c9019426beaa841434c91635c81500>, name = ""] Aug 22 18:55:41 hostname-1 pppd[7678]: rcvd [LCP EchoRep id=0x0 magic=0xe3b6f0 26 11 68 d6] Aug 22 18:55:41 hostname-1 pppd[7678]: rcvd [CHAP Success id=0x1 ""] Aug 22 18:55:41 hostname-1 pppd[7678]: CHAP authentication succeeded Aug 22 18:55:41 hostname-1 pppd[7678]: CHAP authentication succeeded Aug 22 18:55:41 hostname-1 pppd[7678]: sent [CCP ConfReq id=0x1 <deflate 15> <deflate(old#) 15> <bsd v1 15>] Aug 22 18:55:41 hostname-1 pppd[7678]: sent [IPCP ConfReq id=0x1 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 0.0.0.0> <ms-dns2 0.0.0.0>] Aug 22 18:55:41 hostname-1 pppd[7678]: rcvd [LCP ProtRej id=0x2 80 fd 01 01 00 0f 1a 04 78 00 18 04 78 00 15 03 2f] Aug 22 18:55:41 hostname-1 pppd[7678]: Protocol-Reject for 'Compression Control Protocol' (0x80fd) received Aug 22 18:55:42 hostname-1 pppd[7678]: rcvd [IPCP ConfNak id=0x1 <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>] Aug 22 18:55:42 hostname-1 pppd[7678]: sent [IPCP ConfReq id=0x2 <compress VJ 0f 01> <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>] Aug 22 18:55:42 hostname-1 pppd[7678]: rcvd [IPCP ConfReq id=0x0] Aug 22 18:55:42 hostname-1 pppd[7678]: sent [IPCP ConfNak id=0x0 <addr 0.0.0.0>] Aug 22 18:55:42 hostname-1 pppd[7678]: rcvd [IPCP ConfRej id=0x2 <compress VJ 0f 01> <ms-wins 10.11.12.13> <ms-wins 10.11.12.14>] Aug 22 18:55:42 hostname-1 pppd[7678]: sent [IPCP ConfReq id=0x3 <addr 0.0.0.0> <ms-dns1 10.11.12.13> <ms-dns2 10.11.12.14>] Aug 22 18:55:42 hostname-1 pppd[7678]: rcvd [IPCP ConfReq id=0x1] Aug 22 18:55:42 hostname-1 pppd[7678]: sent [IPCP ConfAck id=0x1] Aug 22 18:55:42 hostname-1 pppd[7678]: rcvd [IPCP ConfNak id=0x3 <addr 11.11.11.11> <ms-dns1 217.171.132.1> <ms-dns2 217.171.132.1>] Aug 22 18:55:42 hostname-1 pppd[7678]: sent [IPCP ConfReq id=0x4 <addr 11.11.11.11> <ms-dns1 217.171.132.1> <ms-dns2 217.171.132.1>] Aug 22 18:55:42 hostname-1 pppd[7678]: rcvd [IPCP ConfAck id=0x4 <addr 11.11.11.11> <ms-dns1 217.171.132.1> <ms-dns2 217.171.132.1>] Aug 22 18:55:42 hostname-1 pppd[7678]: Could not determine remote IP address: defaulting to 12.12.12.12 Aug 22 18:55:42 hostname-1 NetworkManager[6336]: <debug> [1345658142.549065] [nm-netlink-monitor.c:163] link_msg_handler(): netlink link message: iface idx 9 flags 0x110D1 Aug 22 18:55:42 hostname-1 pppd[7678]: local IP address 11.11.11.11 Aug 22 18:55:42 hostname-1 pppd[7678]: remote IP address 12.12.12.12 Aug 22 18:55:42 hostname-1 pppd[7678]: primary DNS address 217.171.132.1 Aug 22 18:55:42 hostname-1 pppd[7678]: secondary DNS address 217.171.132.1 Aug 22 18:55:42 hostname-1 NetworkManager[6336]: <info> PPP manager(IP Config Get) reply received. Aug 22 18:55:42 hostname-1 NetworkManager[6336]: nm_ip4_config_add_nameserver: assertion `nameserver != s' failed Aug 22 18:55:42 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 5 of 5 (IPv4 Configure Commit) scheduled... Aug 22 18:55:42 hostname-1 pppd[7678]: Script /etc/ppp/ip-up started (pid 7681) Aug 22 18:55:42 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 5 of 5 (IPv4 Commit) started... Aug 22 18:55:42 hostname-1 NetworkManager[6336]: <debug> [1345658142.553215] [nm-system.c:196] sync_addresses(): (ppp0): syncing addresses (family 2) Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.553959] [nm-netlink-utils.c:360] dump_route(): route idx 9 family INET (2) addr 12.12.12.12/32 Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.554005] [nm-netlink-utils.c:360] dump_route(): route idx 9 family INET (2) addr 11.11.11.11/32 Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.554024] [nm-netlink-utils.c:360] dump_route(): route idx 1 family INET (2) addr 127.0.0.0/32 Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.554040] [nm-netlink-utils.c:360] dump_route(): route idx 1 family INET (2) addr 127.0.0.0/8 Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.554056] [nm-netlink-utils.c:360] dump_route(): route idx 1 family INET (2) addr 127.0.0.1/32 Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.554073] [nm-netlink-utils.c:360] dump_route(): route idx 1 family INET (2) addr 127.255.255.255/32 Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.554153] [nm-dns-manager.c:709] update_dns(): DNS: updating plugin dnsmasq Aug 22 18:55:43 hostname-1 dnsmasq[7469]: exiting on receipt of SIGTERM Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.554369] [nm-dns-dnsmasq.c:337] update(): dnsmasq local caching DNS configuration: Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.554392] [nm-dns-dnsmasq.c:338] update(): server=217.171.132.1 Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <info> DNS: starting dnsmasq... Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.554475] [nm-dns-plugin.c:173] nm_dns_plugin_child_spawn(): DNS: command line: /usr/sbin/dnsmasq --no-resolv --keep-in-foreground --no-hosts --bind-interfaces --pid-file=/var/run/sendsigs.omit.d/network-manager.dnsmasq.pid --listen-address=127.0.0.1 --conf-file=/var/run/nm-dns-dnsmasq.conf --cache-size=0 --proxy-dnssec Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <debug> [1345658143.556437] [nm-dns-plugin.c:182] nm_dns_plugin_child_spawn(): dnsmasq started with pid 7718 Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <info> (ppp0): writing resolv.conf to /sbin/resolvconf Aug 22 18:55:43 hostname-1 dnsmasq[7718]: started, version 2.59 cache disabled Aug 22 18:55:43 hostname-1 dnsmasq[7718]: compile time options: IPv6 GNU-getopt DBus i18n DHCP TFTP conntrack IDN Aug 22 18:55:43 hostname-1 dnsmasq[7718]: using nameserver 217.171.132.1#53 Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): device state change: ip-config -> activated (reason 'none') [70 100 0] Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <info> Policy set '3 Internet' (ppp0) as default for IPv4 routing and DNS. Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) successful, device activated. Aug 22 18:55:43 hostname-1 NetworkManager[6336]: <info> Activation (ttyUSB0) Stage 5 of 5 (IPv4 Commit) complete. Aug 22 18:55:43 hostname-1 dbus[1222]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper) Aug 22 18:55:43 hostname-1 dbus[1222]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Aug 22 18:55:44 hostname-1 pppd[7678]: Script /etc/ppp/ip-up finished (pid 7681), status = 0x0 Aug 22 18:55:45 hostname-1 NetworkManager[6336]: <debug> [1345658145.974378] [nm-dns-plugin.c:208] ensure_killed(): waiting for dnsmasq pid 7469 to exit Aug 22 18:55:45 hostname-1 NetworkManager[6336]: <debug> [1345658145.974484] [nm-dns-plugin.c:210] ensure_killed(): dnsmasq pid 7469 cleaned up Aug 22 18:55:52 hostname-1 ntpdate[7752]: adjust time server 91.189.94.4 offset 0.015714 sec Aug 22 19:01:33 hostname-1 pppd[7678]: rcvd [LCP TermReq id=0x3] Aug 22 19:01:33 hostname-1 pppd[7678]: LCP terminated by peer Aug 22 19:01:33 hostname-1 pppd[7678]: Connect time 5.9 minutes. Aug 22 19:01:33 hostname-1 pppd[7678]: Sent 15185 bytes, received 38410 bytes. Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.218402] [nm-netlink-monitor.c:163] link_msg_handler(): netlink link message: iface idx 9 flags 0x1090 Aug 22 19:01:33 hostname-1 pppd[7678]: Script /etc/ppp/ip-down started (pid 7820) Aug 22 19:01:33 hostname-1 pppd[7678]: sent [LCP TermAck id=0x3] Aug 22 19:01:33 hostname-1 pppd[7678]: Modem hangup Aug 22 19:01:33 hostname-1 pppd[7678]: Connection terminated. Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): device state change: activated -> failed (reason 'ip-config-unavailable') [100 120 5] Aug 22 19:01:33 hostname-1 avahi-daemon[1248]: Withdrawing workstation service for ppp0. Aug 22 19:01:33 hostname-1 modem-manager[5990]: <info> (ttyUSB0) closing serial port... Aug 22 19:01:33 hostname-1 modem-manager[5990]: <info> (ttyUSB0) serial port closed Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <warn> Activation (ttyUSB0) failed. Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.245218] [nm-device.c:4406] nm_device_queue_state(): (ttyUSB0): queued state change to disconnected (id 202) Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.246649] [nm-netlink-monitor.c:163] link_msg_handler(): netlink link message: iface idx 9 flags 0x1090 Aug 22 19:01:33 hostname-1 NetworkManager[6336]: SCPlugin-Ifupdown: devices removed (path: /sys/devices/virtual/net/ppp0, iface: ppp0) Aug 22 19:01:33 hostname-1 modem-manager[5990]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (connected -> disconnecting) Aug 22 19:01:33 hostname-1 modem-manager[5990]: <info> Modem /org/freedesktop/ModemManager/Modems/1: state changed (disconnecting -> connected) Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.247703] [nm-udev-manager.c:476] handle_uevent(): UDEV event: action 'remove' subsys 'net' device 'ppp0' Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): now unmanaged Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): device state change: failed -> unmanaged (reason 'removed') [120 10 36] Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.248114] [nm-device.c:2891] queued_state_clear(): (ttyUSB0): clearing queued state transition (id 202) Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): deactivating device (reason 'removed') [36] Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.248385] [nm-firewall-manager.c:157] nm_firewall_manager_remove_from_zone(): (ppp0) firewall zone remove skipped (not running) Aug 22 19:01:33 hostname-1 dbus[1222]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper) Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <warn> could not read ppp stats: No such device Aug 22 19:01:33 hostname-1 NetworkManager[6336]: nm_system_iface_flush_routes: assertion `ifindex > 0' failed Aug 22 19:01:33 hostname-1 NetworkManager[6336]: nm_system_iface_flush_addresses: assertion `ifindex > 0' failed Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.265283] [nm-dns-manager.c:709] update_dns(): DNS: updating plugin dnsmasq Aug 22 19:01:33 hostname-1 dnsmasq[7718]: exiting on receipt of SIGTERM Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.265404] [nm-dns-dnsmasq.c:337] update(): dnsmasq local caching DNS configuration: Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.265414] [nm-dns-dnsmasq.c:338] update(): Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> DNS: starting dnsmasq... Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.265460] [nm-dns-plugin.c:173] nm_dns_plugin_child_spawn(): DNS: command line: /usr/sbin/dnsmasq --no-resolv --keep-in-foreground --no-hosts --bind-interfaces --pid-file=/var/run/sendsigs.omit.d/network-manager.dnsmasq.pid --listen-address=127.0.0.1 --conf-file=/var/run/nm-dns-dnsmasq.conf --cache-size=0 --proxy-dnssec Aug 22 19:01:33 hostname-1 dnsmasq[7854]: started, version 2.59 cache disabled Aug 22 19:01:33 hostname-1 dnsmasq[7854]: compile time options: IPv6 GNU-getopt DBus i18n DHCP TFTP conntrack IDN Aug 22 19:01:33 hostname-1 dnsmasq[7854]: warning: no upstream servers configured Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <debug> [1345658493.270043] [nm-dns-plugin.c:182] nm_dns_plugin_child_spawn(): dnsmasq started with pid 7854 Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): writing resolv.conf to /sbin/resolvconf Aug 22 19:01:33 hostname-1 dbus[1222]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher' Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): cleaning up... Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> (ttyUSB0): taking down device. Aug 22 19:01:33 hostname-1 pppd[7678]: Script /etc/ppp/ip-down finished (pid 7820), status = 0x0 Aug 22 19:01:33 hostname-1 pppd[7678]: Exit. Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889) Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> Unmanaged Device found; state CONNECTED forced. (see http://bugs.launchpad.net/bugs/191889) Aug 22 19:01:33 hostname-1 NetworkManager[6336]: <info> disconnect failed: (32) The serial port is not open. Aug 22 19:01:35 hostname-1 NetworkManager[6336]: <debug> [1345658495.975690] [nm-ppp-manager.c:1054] ensure_killed(): waiting for pppd pid 7678 to exit Aug 22 19:01:35 hostname-1 NetworkManager[6336]: <debug> [1345658495.975793] [nm-ppp-manager.c:1056] ensure_killed(): pppd pid 7678 cleaned up Aug 22 19:01:35 hostname-1 NetworkManager[6336]: <debug> [1345658495.975811] [nm-dns-plugin.c:208] ensure_killed(): waiting for dnsmasq pid 7718 to exit Aug 22 19:01:35 hostname-1 NetworkManager[6336]: <debug> [1345658495.975865] [nm-dns-plugin.c:210] ensure_killed(): dnsmasq pid 7718 cleaned up |