While working on the JFLTETMO (Samsung Galaxy S4) I ran into an error with the WiFi hotspot, but only after flashing my custom kernel. So, I grabbed my USB cable, and pulled a logcat over ADB, while trying to use the WiFi hotspot feature.
Here’s what the logs read:
[CODE]
01-26 10:42:10.483 578 723 D AudioService: Stream muted, skip playback
01-26 10:42:10.488 264 624 D SoftapController: Softap fwReload – Ok
01-26 10:42:11.622 578 712 D wifi : set interface wlan0 flags (UP)
01-26 10:42:11.622 578 712 I WifiHAL : Initializing wifi
01-26 10:42:11.622 578 712 I WifiHAL : Creating socket
01-26 10:42:11.631 578 712 I WifiHAL : Initialized Wifi HAL Successfully; vendor cmd = 103
01-26 10:42:11.631 578 712 D wifi : Did set static halHandle = 0x9c9380e0
01-26 10:42:11.631 578 712 D wifi : halHandle = 0x9c9380e0, mVM = 0xb42f8000, mCls = 0x201fb2
01-26 10:42:11.631 578 712 D wifi : array field set
01-26 10:42:11.645 578 712 E wifi : failed to get channel list : -95
01-26 10:42:11.645 578 712 D wifi : set country code: US
01-26 10:42:11.651 578 10453 I WifiNative-HAL: Waiting for HAL events mWifiHalHandle=-1668054816
01-26 10:42:11.651 578 10453 D wifi : waitForHalEvents called, vm = 0xb42f8000, obj = 0x201fb2, env = 0x9cc0ecd0
01-26 10:42:11.654 264 624 D SoftapController: SoftAP started successfully
01-26 10:42:11.751 10455 10455 E hostapd : Configuration file: /data/misc/wifi/hostapd.conf
01-26 10:42:11.765 10455 10455 I hostapd : rfkill: Cannot open RFKILL control device
01-26 10:42:11.785 10455 10455 E hostapd : Using interface wlan0 with hwaddr d0:22:be:45:9e:d0 and ssid “AndroidAPun”
01-26 10:42:11.854 264 624 D SoftapController: /data/misc/wifi/sockets already exists
01-26 10:42:11.855 264 10471 D SoftapController: SoftapController::threadStart…
01-26 10:42:11.855 264 10471 D SoftapController: /data/misc/wifi/sockets already exists
01-26 10:42:11.856 578 712 D SoftApManager: Soft AP is started
01-26 10:42:11.871 10455 10455 I hostapd : wlan0: interface state UNINITIALIZED->ENABLED
01-26 10:42:11.871 10455 10455 I hostapd : wlan0: AP-ENABLED
01-26 10:42:11.871 578 712 E wifi : wifi_get_supported_feature_set returned error = 0xffffffa1
01-26 10:42:11.872 578 609 E BatteryStatsService: no controller energy info supplied
01-26 10:42:11.898 264 624 D CommandListener: Setting iface cfg
01-26 10:42:11.900 264 624 D CommandListener: Trying to bring up wlan0
01-26 10:42:11.909 264 624 D TetherController: tetherInterface(wlan0)
01-26 10:42:12.052 264 624 D TetherController: Setting IP forward enable = 1
01-26 10:42:12.058 264 624 D TetherController: Starting tethering services
01-26 10:42:12.060 264 624 D TetherController: Sending update msg to dnsmasq [update_ifaces|wlan0]
01-26 10:42:12.060 264 624 D TetherController: Tethering services running
01-26 10:42:12.064 578 578 D Tethering: got Sim changed to state LOADED, mSimAbsentSeen=false
01-26 10:42:12.064 578 628 D ConnectivityService: requestNetwork for uid/pid:1000/578 NetworkRequest [ TRACK_DEFAULT id=9, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN] ]
01-26 10:42:12.067 578 735 D Ethernet: got request NetworkRequest [ TRACK_DEFAULT id=9, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN] ] with score 50
01-26 10:42:12.068 578 712 D WIFI : got request NetworkRequest [ TRACK_DEFAULT id=9, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN] ] with score 50
01-26 10:42:12.068 578 712 D WIFI_UT : got request NetworkRequest [ TRACK_DEFAULT id=9, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN] ] with score 50
01-26 10:42:12.069 923 923 D PhoneSwitcherNetworkRequstListener: got request NetworkRequest [ TRACK_DEFAULT id=9, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN] ] with score 50
01-26 10:42:12.072 578 707 W ConnectivityExtension: ConnectivityExt jar file not present
01-26 10:42:12.103 578 628 W ConnectivityExtension: ConnectivityExt jar file not present
01-26 10:42:12.104 578 628 I Tethering: Finding IPv4 upstream interface on: {InterfaceName: rmnet_usb0 LinkAddresses: [10.44.167.240/30,] Routes: [0.0.0.0/0 -> 10.44.167.241 rmnet_usb0,] DnsAddresses: [172.20.64.179,172.20.64.180,] Domains: null MTU: 1410 TcpBufferSizes: 2097152,4194304,8388608,262144,524288,1048576}
01-26 10:42:12.104 578 628 I Tethering: Found interface rmnet_usb0
01-26 10:42:12.105 264 624 D TetherController: setDnsForwarders(0xf0064 0 = ‘172.20.64.179’)
01-26 10:42:12.106 264 624 D TetherController: setDnsForwarders(0xf0064 1 = ‘172.20.64.180’)
01-26 10:42:12.106 264 624 D TetherController: Sending update msg to dnsmasq [update_dns|0xf0064|172.20.64.179|172.20.64.180]
01-26 10:42:12.110 264 624 V NatController: enableNat(intIface=, extIface=)
01-26 10:42:12.125 10499 10499 I dnsmasq : started, version 2.51 cachesize 150
01-26 10:42:12.125 10499 10499 I dnsmasq : compile time options: IPv6 GNU-getopt no-DBus no-I18N DHCP no-scripts no-TFTP
01-26 10:42:12.125 10499 10499 W dnsmasq : warning: no upstream servers configured
01-26 10:42:12.125 10499 10499 I dnsmasq : DHCP, IP range 192.168.49.2 — 192.168.49.254, lease time 1h
01-26 10:42:12.126 10499 10499 I dnsmasq : DHCP, IP range 192.168.48.2 — 192.168.48.254, lease time 1h
01-26 10:42:12.126 10499 10499 I dnsmasq : DHCP, IP range 192.168.47.2 — 192.168.47.254, lease time 1h
01-26 10:42:12.127 10499 10499 I dnsmasq : DHCP, IP range 192.168.46.2 — 192.168.46.254, lease time 1h
01-26 10:42:12.127 10499 10499 I dnsmasq : DHCP, IP range 192.168.45.2 — 192.168.45.254, lease time 1h
01-26 10:42:12.127 10499 10499 I dnsmasq : DHCP, IP range 192.168.44.2 — 192.168.44.254, lease time 1h
01-26 10:42:12.127 10499 10499 I dnsmasq : DHCP, IP range 192.168.43.2 — 192.168.43.254, lease time 1h
01-26 10:42:12.127 10499 10499 I dnsmasq : DHCP, IP range 192.168.42.2 — 192.168.42.254, lease time 1h
01-26 10:42:12.127 10499 10499 I dnsmasq : read /etc/hosts – 2 addresses
01-26 10:42:12.128 10499 10499 I dnsmasq : Closing wildcard listener family=2
01-26 10:42:12.128 10499 10499 I dnsmasq : Closing wildcard listener family=10
01-26 10:42:12.129 10499 10499 I dnsmasq : using nameserver 172.20.64.180#53
01-26 10:42:12.129 10499 10499 I dnsmasq : using nameserver 172.20.64.179#53
01-26 10:42:12.146 264 624 V NatController: runCmd(/system/bin/iptables -w -t nat -A natctrl_nat_POSTROUTING -o rmnet_usb0 -j MASQUERADE) res=0
01-26 10:42:12.168 264 624 V NatController: runCmd(/system/bin/ip6tables -w -A natctrl_FORWARD -g natctrl_tether_counters) res=0
01-26 10:42:12.190 264 624 V NatController: runCmd(/system/bin/iptables -w -A natctrl_FORWARD -i rmnet_usb0 -o wlan0 -m state –state ESTABLISHED,RELATED -g natctrl_tether_counters) res=0
01-26 10:42:12.221 264 624 V NatController: runCmd(/system/bin/iptables -w -A natctrl_FORWARD -i wlan0 -o rmnet_usb0 -m state –state INVALID -j DROP) res=0
01-26 10:42:12.245 264 624 V NatController: runCmd(/system/bin/iptables -w -A natctrl_FORWARD -i wlan0 -o rmnet_usb0 -g natctrl_tether_counters) res=0
01-26 10:42:12.285 264 624 V NatController: runCmd(/system/bin/ip6tables -w -t raw -A natctrl_raw_PREROUTING -i wlan0 -m rpfilter –invert ! -s fe80::/64 -j DROP) res=1
01-26 10:42:12.337 264 624 V NatController: runCmd(/system/bin/iptables -w -D natctrl_FORWARD -i wlan0 -o rmnet_usb0 -g natctrl_tether_counters) res=0
01-26 10:42:12.373 264 624 V NatController: runCmd(/system/bin/iptables -w -D natctrl_FORWARD -i wlan0 -o rmnet_usb0 -m state –state INVALID -j DROP) res=0
01-26 10:42:12.405 264 624 V NatController: runCmd(/system/bin/iptables -w -D natctrl_FORWARD -i rmnet_usb0 -o wlan0 -m state –state ESTABLISHED,RELATED -g natctrl_tether_counters) res=0
01-26 10:42:12.405 264 624 E NatController: Error setting forward rules
01-26 10:42:12.435 264 624 V NatController: runCmd(/system/bin/iptables -w -F natctrl_FORWARD) res=0
01-26 10:42:12.464 264 624 V NatController: runCmd(/system/bin/ip6tables -w -F natctrl_FORWARD) res=0
01-26 10:42:12.494 2699 2715 E MP-Decision: Error(-22) changing core 3 status to offline
01-26 10:42:12.494 2699 2715 E MP-Decision: Error(-22) changing core 2 status to offline
01-26 10:42:12.494 2699 2715 E MP-Decision: Error(-22) changing core 1 status to offline
01-26 10:42:12.541 264 624 V NatController: runCmd(/system/bin/iptables -w -A natctrl_FORWARD -j DROP) res=0
01-26 10:42:12.577 264 624 V NatController: runCmd(/system/bin/iptables -w -t nat -F natctrl_nat_POSTROUTING) res=0
01-26 10:42:12.614 264 624 V NatController: runCmd(/system/bin/ip6tables -w -t raw -F natctrl_raw_PREROUTING) res=0
01-26 10:42:12.616 578 628 E NetdConnector: NDC Command {82 nat enable wlan0 rmnet_usb0 1 192.168.43.0/24} took too long (507ms)
01-26 10:42:12.618 578 628 E TetherInterfaceSM: Exception enabling Nat: java.lang.IllegalStateException: command ’82 nat enable wlan0 rmnet_usb0 1 192.168.43.0/24′ failed with ‘400 82 Nat operation failed (No such device)’
01-26 10:42:12.620 264 625 D TetherController: Sending update msg to dnsmasq [update_ifaces|wlan0]
01-26 10:42:12.623 264 624 D TetherController: untetherInterface(wlan0)
01-26 10:42:12.695 264 624 D CommandListener: Setting iface cfg
01-26 10:42:12.699 264 624 D CommandListener: Trying to bring down wlan0
01-26 10:42:12.948 10455 10455 I hostapd : wlan0: INTERFACE-DISABLED
01-26 10:42:12.966 264 624 D TetherController: setDnsForwarders(0xf0064 0 = ‘172.20.64.179’)
01-26 10:42:12.966 264 624 D TetherController: setDnsForwarders(0xf0064 1 = ‘172.20.64.180’)
01-26 10:42:12.966 264 624 D TetherController: Sending update msg to dnsmasq [update_dns|0xf0064|172.20.64.179|172.20.64.180]
01-26 10:42:12.968 10499 10499 I dnsmasq : using nameserver 172.20.64.180#53
01-26 10:42:12.968 10499 10499 I dnsmasq : using nameserver 172.20.64.179#53
01-26 10:42:12.984 264 624 D TetherController: Stopping tethering services
01-26 10:42:12.984 10499 10499 I dnsmasq : exiting on receipt of SIGTERM
01-26 10:42:12.986 264 624 D TetherController: Tethering services stopped
01-26 10:42:12.997 264 624 D TetherController: Setting IP forward enable = 0
01-26 10:42:13.002 578 716 D ConnectivityService: releasing NetworkRequest [ TRACK_DEFAULT id=9, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&NOT_VPN] ]
01-26 10:42:13.101 578 707 W ConnectivityExtension: ConnectivityExt jar file not present
01-26 10:42:13.504 2699 2715 E MP-Decision: Error(-22) changing core 3 status to offline
01-26 10:42:13.505 2699 2715 E MP-Decision: Error(-22) changing core 2 status to offline
01-26 10:42:13.505 2699 2715 E MP-Decision: Error(-22) changing core 1 status to offline
01-26 10:42:13.875 264 10471 D SoftapController: Get event from hostapd (INTERFACE-DISABLED )
01-26 10:42:13.877 578 627 D NetworkManagement: onEvent: 618 90 IfaceMessage active INTERFACE-DISABLED
01-26 10:42:13.877 578 627 E NetdConnector: Error handling ‘618 90 IfaceMessage active INTERFACE-DISABLED ‘: java.lang.ArrayIndexOutOfBoundsException: length=5; index=5
[/CODE]
There is a lot in there, but one of the highlights is that it did start the interface, set it up, and then couldn’t forward anything on it:
01-26 10:42:12.405 264 624 E NatController: Error setting forward rules
So, I ran back through my configurations, and compared them to the original CM configs, and found two things that I should enable. You can check out the commit here:
Essentially, I enabled Reverse Path Filtering, you can read about it here. Basically, it filters out what should be ignored or included as a packet to/from your network. I can’t believe that I missed that. Seems pretty integral to packet forwarding, routing, and other “path” tools for packets. By God’s grace, enabling it fixed the problem and made the WiFi hotspot work again!
Linux – keep it simple.