search

aparcar / openwrt

Staging tree of Paul Spooren
Other
9 stars 1 forks source link

FS#493 - strongSwan no known IPsec stack detected since switch to kernel 4.9 #563

Closed aparcar closed 7 years ago

aparcar commented 7 years ago

kpv:

On a newly compiled LEDE r3374 trunk VM with kernel 4.9.8, strongSwan reports IPsec stack missing, possibly due to xfrm_* dependencies missing. My previous build with same config from 2 days ago (with kernel 4.4.x) seemed OK:

usyBox v1.26.2 () built-in shell (ash)

 _________
/        /\      _    ___ ___  ___

/ LE / \ | | | | | | / DE / \ | || || |) | | /__/ LE \ |__|__|/|_| lede-project.org \ \ DE / \ LE \ / ----------------------------------------------------------- \ DE \ / Reboot (SNAPSHOT, r3374-fe1e362) ______\/ -----------------------------------------------------------

root@LEDE:~#

root@LEDE:~# logread ... Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.858558] kmodloader: 8 modules could not be probed Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.860471] kmodloader: missing dependency xfrm_algo Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.872219] kmodloader: - af_key - 1 Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.874243] kmodloader: missing dependency xfrm_algo Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.876215] kmodloader: - ah4 - 1 Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.878142] kmodloader: missing dependency xfrm_algo Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.880019] kmodloader: - ah6 - 1 Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.890067] kmodloader: missing dependency xfrm_algo Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.901452] kmodloader: - esp4 - 1 Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.903455] kmodloader: missing dependency xfrm_algo Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.905392] kmodloader: - esp6 - 1 Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.907195] kmodloader: missing dependency xfrm_ipcomp Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.910457] kmodloader: - ipcomp - 1 Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.921727] kmodloader: missing dependency xfrm_ipcomp Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.923874] kmodloader: - ipcomp6 - 1 Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.925643] kmodloader: missing dependency xfrm_algo Thu Feb 9 20:18:52 2017 user.err kernel: [ 10.927613] kmodloader: - xfrm_user - 1 Thu Feb 9 20:18:53 2017 user.notice : Added device handler type: tunnel Thu Feb 9 20:18:53 2017 user.notice : Added device handler type: Network device Thu Feb 9 20:18:53 2017 user.notice : Added device handler type: bridge Thu Feb 9 20:18:53 2017 user.notice : Added device handler type: macvlan Thu Feb 9 20:18:53 2017 user.notice : Added device handler type: 8021ad Thu Feb 9 20:18:53 2017 user.notice : Added device handler type: 8021q Thu Feb 9 20:18:54 2017 kern.notice kernel: [ 14.764420] random: crng init done Thu Feb 9 20:18:54 2017 authpriv.warn dropbear[1814]: Failed loading /etc/dropbear/dropbear_ecdsa_host_key Thu Feb 9 20:18:54 2017 authpriv.info dropbear[1814]: Not backgrounding Thu Feb 9 20:18:55 2017 kern.info kernel: [ 15.950825] 8021q: adding VLAN 0 to HW filter on device eth0 Thu Feb 9 20:18:55 2017 kern.info kernel: [ 15.953210] br-lan: port 1(eth0) entered blocking state Thu Feb 9 20:18:55 2017 kern.info kernel: [ 15.957430] br-lan: port 1(eth0) entered disabled state Thu Feb 9 20:18:55 2017 kern.info kernel: [ 15.959553] device eth0 entered promiscuous mode Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'lan' is enabled Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'lan' is setting up now Thu Feb 9 20:18:55 2017 kern.info kernel: [ 15.989534] br-lan: port 1(eth0) entered blocking state Thu Feb 9 20:18:55 2017 kern.info kernel: [ 15.991689] br-lan: port 1(eth0) entered forwarding state Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'lan' is now up Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'loopback' is enabled Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'loopback' is setting up now Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'loopback' is now up Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'wan' is enabled Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'wan6' is enabled Thu Feb 9 20:18:55 2017 daemon.notice netifd: bridge 'br-lan' link is up Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'lan' has link connectivity Thu Feb 9 20:18:55 2017 daemon.notice netifd: Network device 'eth0' link is up Thu Feb 9 20:18:55 2017 daemon.notice netifd: Network device 'lo' link is up Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'loopback' has link connectivity Thu Feb 9 20:18:55 2017 daemon.notice netifd: Network device 'eth1' link is up Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'wan' has link connectivity Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'wan' is setting up now Thu Feb 9 20:18:55 2017 kern.info kernel: [ 16.042670] 8021q: adding VLAN 0 to HW filter on device eth1 Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'wan6' has link connectivity Thu Feb 9 20:18:55 2017 daemon.notice netifd: Interface 'wan6' is setting up now Thu Feb 9 20:18:55 2017 daemon.info odhcpd[1766]: Raising SIGUSR1 due to address change on br-lan Thu Feb 9 20:18:55 2017 daemon.notice netifd: wan (1954): udhcpc: started, v1.26.2 Thu Feb 9 20:18:55 2017 daemon.notice netifd: wan (1954): udhcpc: sending discover Thu Feb 9 20:18:56 2017 user.notice firewall: Reloading firewall due to ifup of lan (br-lan) Thu Feb 9 20:18:56 2017 daemon.notice netifd: wan (1954): udhcpc: sending select for 10.0.3.105 Thu Feb 9 20:18:56 2017 daemon.notice netifd: wan (1954): udhcpc: lease of 10.0.3.105 obtained, lease time 3600 Thu Feb 9 20:18:56 2017 daemon.info odhcpd[1766]: Initial RA router lifetime 0, 1 address(es) available on br-lan Thu Feb 9 20:18:56 2017 daemon.notice odhcpd[1766]: Failed to send to ff02::1%br-lan (Address not available) Thu Feb 9 20:18:56 2017 daemon.err odhcp6c[1953]: Failed to send DHCPV6 message to ff02::1:2 (Address not available) Thu Feb 9 20:18:56 2017 daemon.notice netifd: Interface 'wan' is now up Thu Feb 9 20:18:56 2017 user.notice : no files found matching '/etc/strongswan.d/*.conf' Thu Feb 9 20:18:56 2017 user.notice : Starting strongSwan 5.5.1 IPsec [starter]... Thu Feb 9 20:18:56 2017 authpriv.info ipsec_starter[2068]: Starting strongSwan 5.5.1 IPsec [starter]... Thu Feb 9 20:18:56 2017 daemon.err modprobe: failed to find dependency xfrm_algo Thu Feb 9 20:18:56 2017 daemon.err modprobe: 1 module could not be probed Thu Feb 9 20:18:56 2017 daemon.err modprobe: - af_key Thu Feb 9 20:18:56 2017 authpriv.info ipsec_starter[2068]: no netkey IPsec stack detected Thu Feb 9 20:18:56 2017 user.notice : no netkey IPsec stack detected Thu Feb 9 20:18:56 2017 user.notice : modprobe: unrecognized option: v Thu Feb 9 20:18:56 2017 daemon.info modprobe: Usage: modprobe [-q] filename Thu Feb 9 20:18:56 2017 authpriv.info ipsec_starter[2068]: no KLIPS IPsec stack detected Thu Feb 9 20:18:56 2017 authpriv.info ipsec_starter[2068]: no known IPsec stack detected, ignoring! Thu Feb 9 20:18:56 2017 user.notice : no KLIPS IPsec stack detected Thu Feb 9 20:18:56 2017 user.notice : no known IPsec stack detected, ignoring! Thu Feb 9 20:18:56 2017 daemon.info : 00[DMN] Starting IKE charon daemon (strongSwan 5.5.1, Linux 4.9.8, i686) Thu Feb 9 20:18:57 2017 daemon.err modprobe: failed to find dependency xfrm_algo Thu Feb 9 20:18:57 2017 daemon.err modprobe: 1 module could not be probed Thu Feb 9 20:18:57 2017 daemon.err modprobe: - xfrm_user Thu Feb 9 20:18:57 2017 daemon.info : 00[KNL] unable to create netlink socket: Protocol not supported (93) Thu Feb 9 20:18:57 2017 daemon.info : 00[NET] installing IKE bypass policy failed Thu Feb 9 20:18:57 2017 daemon.info : 00[NET] installing IKE bypass policy failed Thu Feb 9 20:18:57 2017 daemon.info : 00[NET] enabling UDP decapsulation for IPv6 on port 4500 failed Thu Feb 9 20:18:57 2017 daemon.info : 00[NET] installing IKE bypass policy failed Thu Feb 9 20:18:57 2017 daemon.info : 00[NET] installing IKE bypass policy failed Thu Feb 9 20:18:57 2017 daemon.info : 00[NET] enabling UDP decapsulation for IPv4 on port 4500 failed Thu Feb 9 20:18:57 2017 daemon.info : 00[LIB] feature CUSTOM:libcharon in critical plugin 'charon' has unmet dependency: CUSTOM:kernel-ipsec Thu Feb 9 20:18:57 2017 daemon.info : 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts' Thu Feb 9 20:18:57 2017 daemon.info : 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts' Thu Feb 9 20:18:57 2017 daemon.info : 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts' Thu Feb 9 20:18:57 2017 daemon.info : 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts' Thu Feb 9 20:18:57 2017 daemon.info : 00[CFG] loading crls from '/etc/ipsec.d/crls' Thu Feb 9 20:18:57 2017 daemon.info : 00[CFG] loading secrets from '/etc/ipsec.secrets' Thu Feb 9 20:18:57 2017 daemon.info : 00[LIB] failed to load 1 critical plugin feature Thu Feb 9 20:18:57 2017 daemon.info : 00[DMN] initialization failed - aborting charon Thu Feb 9 20:18:57 2017 authpriv.info ipsec_starter[2091]: charon has quit: initialization failed Thu Feb 9 20:18:57 2017 authpriv.info ipsec_starter[2091]: charon refused to be started Thu Feb 9 20:18:57 2017 authpriv.info ipsec_starter[2091]: ipsec starter stopped Thu Feb 9 20:18:57 2017 daemon.info odhcpd[1766]: Initial RA router lifetime 0, 1 address(es) available on br-lan Thu Feb 9 20:18:57 2017 daemon.info procd: - init complete - Thu Feb 9 20:18:57 2017 daemon.info urandom_seed[2169]: Seed saved (/etc/urandom.seed) Thu Feb 9 20:19:01 2017 user.notice mwan3: ifup interface wan (eth1) Thu Feb 9 20:19:03 2017 user.notice firewall: Reloading firewall due to ifup of wan (eth1) Thu Feb 9 20:19:04 2017 daemon.info dnsmasq[1]: started, version 2.77test1 cachesize 150 Thu Feb 9 20:19:04 2017 daemon.info dnsmasq[1]: DNS service limited to local subnets Thu Feb 9 20:19:04 2017 daemon.info dnsmasq[1]: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP conntrack ipset no-auth no-DNSSEC no-ID loop-detect inotify Thu Feb 9 20:19:04 2017 daemon.info dnsmasq-dhcp[1]: DHCP, IP range 192.168.1.100 -- 192.168.1.249, lease time 12h Thu Feb 9 20:19:04 2017 daemon.info dnsmasq[1]: using local addresses only for domain lan Thu Feb 9 20:19:04 2017 daemon.info dnsmasq[1]: reading /tmp/resolv.conf.auto Thu Feb 9 20:19:04 2017 daemon.info dnsmasq[1]: using local addresses only for domain lan Thu Feb 9 20:19:04 2017 daemon.info dnsmasq[1]: using nameserver 10.0.3.1#53 Thu Feb 9 20:19:04 2017 daemon.info dnsmasq[1]: read /etc/hosts - 4 addresses Thu Feb 9 20:19:04 2017 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg02411c - 2 addresses Thu Feb 9 20:19:04 2017 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses Thu Feb 9 20:19:05 2017 user.notice ddns-scripts[2665]: myddns_ipv4: PID '2665' started at 2017-02-09 20:19 Thu Feb 9 20:19:05 2017 user.warn ddns-scripts[2665]: myddns_ipv4: Service section disabled! - TERMINATE Thu Feb 9 20:19:05 2017 user.warn ddns-scripts[2665]: myddns_ipv4: PID '2665' exit WITH ERROR '1' at 2017-02-09 20:19 Thu Feb 9 20:19:34 2017 daemon.info dnsmasq[1]: read /etc/hosts - 4 addresses Thu Feb 9 20:19:34 2017 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg02411c - 2 addresses Thu Feb 9 20:19:34 2017 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses Thu Feb 9 20:25:51 2017 authpriv.info dropbear[3948]: Child connection from 10.0.3.1:56843 Thu Feb 9 20:25:56 2017 authpriv.notice dropbear[3948]: Password auth succeeded for 'root' from 10.0.3.1:56843

aparcar commented 7 years ago

kpv:

I'm attaching some more info, after re-building latest git trunk:

BusyBox v1.26.2 () built-in shell (ash)

 _________
/        /\      _    ___ ___  ___

/ LE / \ | | | | | | / DE / \ | || || |) | | /__/ LE \ |__|__|/|_| lede-project.org \ \ DE / \ LE \ / ----------------------------------------------------------- \ DE \ / Reboot (SNAPSHOT, r3383-0bf85ef) ______\/ -----------------------------------------------------------

root@LEDE:~# uname -a Linux LEDE 4.9.8 #0 SMP Fri Feb 10 10:05:57 2017 i686 GNU/Linux

root@LEDE:~# opkg list-installed|fgrep -i ipsec iptables-mod-ipsec - 1.4.21-2 kmod-ipsec - 4.9.8-1 kmod-ipsec4 - 4.9.8-1 kmod-ipsec6 - 4.9.8-1 kmod-ipt-ipsec - 4.9.8-1 root@LEDE:~# opkg files kmod-ipsec Package kmod-ipsec (4.9.8-1) is installed on root and has the following files: /lib/modules/4.9.8/af_key.ko /lib/modules/4.9.8/xfrm_ipcomp.ko /etc/modules.d/30-ipsec /lib/modules/4.9.8/xfrm_user.ko /lib/modules/4.9.8/xfrm_algo.ko root@LEDE:~# opkg files kmod-ipsec4 Package kmod-ipsec4 (4.9.8-1) is installed on root and has the following files: /lib/modules/4.9.8/xfrm4_tunnel.ko /lib/modules/4.9.8/xfrm4_mode_transport.ko /lib/modules/4.9.8/esp4.ko /lib/modules/4.9.8/xfrm4_mode_beet.ko /lib/modules/4.9.8/xfrm4_mode_tunnel.ko /etc/modules.d/32-ipsec4 /lib/modules/4.9.8/ipcomp.ko /lib/modules/4.9.8/ah4.ko root@LEDE:~# opkg files kmod-ipsec6 Package kmod-ipsec6 (4.9.8-1) is installed on root and has the following files: /lib/modules/4.9.8/ah6.ko /lib/modules/4.9.8/xfrm6_mode_beet.ko /lib/modules/4.9.8/xfrm6_mode_transport.ko /lib/modules/4.9.8/xfrm6_mode_tunnel.ko /lib/modules/4.9.8/esp6.ko /lib/modules/4.9.8/ipcomp6.ko /etc/modules.d/32-ipsec6 /lib/modules/4.9.8/xfrm6_tunnel.ko root@LEDE:~# root@LEDE:~# logread |tail -100 Fri Feb 10 21:12:40 2017 user.notice : Added device handler type: bridge Fri Feb 10 21:12:40 2017 user.notice : Added device handler type: macvlan Fri Feb 10 21:12:40 2017 user.notice : Added device handler type: 8021ad Fri Feb 10 21:12:40 2017 user.notice : Added device handler type: 8021q Fri Feb 10 21:12:41 2017 authpriv.warn dropbear[1811]: Failed loading /etc/dropbear/dropbear_ecdsa_host_key Fri Feb 10 21:12:41 2017 authpriv.info dropbear[1811]: Not backgrounding Fri Feb 10 21:12:41 2017 kern.info kernel: [ 13.426312] 8021q: adding VLAN 0 to HW filter on device eth0 Fri Feb 10 21:12:41 2017 kern.info kernel: [ 13.428770] br-lan: port 1(eth0) entered blocking state Fri Feb 10 21:12:41 2017 kern.info kernel: [ 13.430726] br-lan: port 1(eth0) entered disabled state Fri Feb 10 21:12:41 2017 kern.info kernel: [ 13.433021] device eth0 entered promiscuous mode Fri Feb 10 21:12:41 2017 kern.info kernel: [ 13.455357] br-lan: port 1(eth0) entered blocking state Fri Feb 10 21:12:41 2017 kern.info kernel: [ 13.457423] br-lan: port 1(eth0) entered forwarding state Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'lan' is enabled Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'lan' is setting up now Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'lan' is now up Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'loopback' is enabled Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'loopback' is setting up now Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'loopback' is now up Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'wan' is enabled Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'wan6' is enabled Fri Feb 10 21:12:41 2017 daemon.notice netifd: bridge 'br-lan' link is up Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'lan' has link connectivity Fri Feb 10 21:12:41 2017 daemon.notice netifd: Network device 'eth0' link is up Fri Feb 10 21:12:41 2017 daemon.notice netifd: Network device 'lo' link is up Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'loopback' has link connectivity Fri Feb 10 21:12:41 2017 daemon.notice netifd: Network device 'eth1' link is up Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'wan' has link connectivity Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'wan' is setting up now Fri Feb 10 21:12:41 2017 kern.info kernel: [ 13.494624] 8021q: adding VLAN 0 to HW filter on device eth1 Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'wan6' has link connectivity Fri Feb 10 21:12:41 2017 daemon.info odhcpd[1766]: Raising SIGUSR1 due to address change on br-lan Fri Feb 10 21:12:41 2017 daemon.notice netifd: Interface 'wan6' is setting up now Fri Feb 10 21:12:42 2017 daemon.notice netifd: wan (1945): udhcpc: started, v1.26.2 Fri Feb 10 21:12:42 2017 daemon.notice netifd: wan (1945): udhcpc: sending discover Fri Feb 10 21:12:42 2017 daemon.notice netifd: wan (1945): udhcpc: sending select for 10.0.3.105 Fri Feb 10 21:12:42 2017 daemon.notice netifd: wan (1945): udhcpc: lease of 10.0.3.105 obtained, lease time 3600 Fri Feb 10 21:12:42 2017 daemon.notice netifd: Interface 'wan' is now up Fri Feb 10 21:12:42 2017 daemon.err odhcp6c[1954]: Failed to send DHCPV6 message to ff02::1:2 (Address not available) Fri Feb 10 21:12:42 2017 user.notice firewall: Reloading firewall due to ifup of lan (br-lan) Fri Feb 10 21:12:43 2017 kern.notice kernel: [ 14.572176] random: crng init done Fri Feb 10 21:12:43 2017 user.notice : no files found matching '/etc/strongswan.d/*.conf' Fri Feb 10 21:12:43 2017 user.notice : Starting strongSwan 5.5.1 IPsec [starter]... Fri Feb 10 21:12:43 2017 authpriv.info ipsec_starter[2060]: Starting strongSwan 5.5.1 IPsec [starter]... Fri Feb 10 21:12:43 2017 daemon.err modprobe: failed to find dependency xfrm_algo Fri Feb 10 21:12:43 2017 daemon.err modprobe: 1 module could not be probed Fri Feb 10 21:12:43 2017 daemon.err modprobe: - af_key Fri Feb 10 21:12:43 2017 authpriv.info ipsec_starter[2060]: no netkey IPsec stack detected Fri Feb 10 21:12:43 2017 user.notice : no netkey IPsec stack detected Fri Feb 10 21:12:43 2017 user.notice : modprobe: unrecognized option: v Fri Feb 10 21:12:43 2017 daemon.info modprobe: Usage: modprobe [-q] filename Fri Feb 10 21:12:43 2017 authpriv.info ipsec_starter[2060]: no KLIPS IPsec stack detected Fri Feb 10 21:12:43 2017 authpriv.info ipsec_starter[2060]: no known IPsec stack detected, ignoring! Fri Feb 10 21:12:43 2017 user.notice : no KLIPS IPsec stack detected Fri Feb 10 21:12:43 2017 user.notice : no known IPsec stack detected, ignoring! Fri Feb 10 21:12:43 2017 daemon.info : 00[DMN] Starting IKE charon daemon (strongSwan 5.5.1, Linux 4.9.8, i686) Fri Feb 10 21:12:43 2017 daemon.err modprobe: failed to find dependency xfrm_algo Fri Feb 10 21:12:43 2017 daemon.err modprobe: 1 module could not be probed Fri Feb 10 21:12:43 2017 daemon.err modprobe: - xfrm_user Fri Feb 10 21:12:43 2017 daemon.info : 00[KNL] unable to create netlink socket: Protocol not supported (93) Fri Feb 10 21:12:43 2017 daemon.info : 00[NET] installing IKE bypass policy failed Fri Feb 10 21:12:43 2017 daemon.info : 00[NET] installing IKE bypass policy failed Fri Feb 10 21:12:43 2017 daemon.info : 00[NET] enabling UDP decapsulation for IPv6 on port 4500 failed Fri Feb 10 21:12:43 2017 daemon.info : 00[NET] installing IKE bypass policy failed Fri Feb 10 21:12:43 2017 daemon.info : 00[NET] installing IKE bypass policy failed Fri Feb 10 21:12:43 2017 daemon.info : 00[NET] enabling UDP decapsulation for IPv4 on port 4500 failed Fri Feb 10 21:12:43 2017 daemon.info : 00[LIB] feature CUSTOM:libcharon in critical plugin 'charon' has unmet dependency: CUSTOM:kernel-ipsec Fri Feb 10 21:12:43 2017 daemon.info : 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts' Fri Feb 10 21:12:43 2017 daemon.info : 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts' Fri Feb 10 21:12:43 2017 daemon.info : 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts' Fri Feb 10 21:12:43 2017 daemon.info : 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts' Fri Feb 10 21:12:43 2017 daemon.info : 00[CFG] loading crls from '/etc/ipsec.d/crls' Fri Feb 10 21:12:43 2017 daemon.info : 00[CFG] loading secrets from '/etc/ipsec.secrets' Fri Feb 10 21:12:43 2017 daemon.info : 00[LIB] failed to load 1 critical plugin feature Fri Feb 10 21:12:43 2017 daemon.info : 00[DMN] initialization failed - aborting charon Fri Feb 10 21:12:43 2017 authpriv.info ipsec_starter[2081]: charon has quit: initialization failed Fri Feb 10 21:12:43 2017 authpriv.info ipsec_starter[2081]: charon refused to be started Fri Feb 10 21:12:43 2017 authpriv.info ipsec_starter[2081]: ipsec starter stopped Fri Feb 10 21:12:43 2017 daemon.info odhcpd[1766]: Initial RA router lifetime 0, 1 address(es) available on br-lan Fri Feb 10 21:12:43 2017 daemon.err odhcp6c[1954]: Failed to send DHCPV6 message to ff02::1:2 (Address not available) Fri Feb 10 21:12:44 2017 daemon.info procd: - init complete - Fri Feb 10 21:12:44 2017 daemon.info urandom_seed[2177]: Seed saved (/etc/urandom.seed) Fri Feb 10 21:12:50 2017 user.notice firewall: Reloading firewall due to ifup of wan (eth1) Fri Feb 10 21:12:50 2017 daemon.info dnsmasq[1]: started, version 2.77test1 cachesize 150 Fri Feb 10 21:12:50 2017 daemon.info dnsmasq[1]: DNS service limited to local subnets Fri Feb 10 21:12:50 2017 daemon.info dnsmasq[1]: compile time options: IPv6 GNU-getopt no-DBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP conntrack ipset no-auth no-DNSSEC no-ID loop-detect inotify Fri Feb 10 21:12:50 2017 daemon.info dnsmasq-dhcp[1]: DHCP, IP range 192.168.1.100 -- 192.168.1.249, lease time 12h Fri Feb 10 21:12:50 2017 daemon.info dnsmasq[1]: using local addresses only for domain lan Fri Feb 10 21:12:50 2017 daemon.info dnsmasq[1]: reading /tmp/resolv.conf.auto Fri Feb 10 21:12:50 2017 daemon.info dnsmasq[1]: using local addresses only for domain lan Fri Feb 10 21:12:50 2017 daemon.info dnsmasq[1]: using nameserver 10.0.3.1#53 Fri Feb 10 21:12:50 2017 daemon.info dnsmasq[1]: read /etc/hosts - 4 addresses Fri Feb 10 21:12:50 2017 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg02411c - 2 addresses Fri Feb 10 21:12:50 2017 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses Fri Feb 10 21:12:51 2017 user.notice ddns-scripts[2689]: myddns_ipv4: PID '2689' started at 2017-02-10 21:12 Fri Feb 10 21:12:51 2017 user.warn ddns-scripts[2689]: myddns_ipv4: Service section disabled! - TERMINATE Fri Feb 10 21:12:51 2017 user.warn ddns-scripts[2689]: myddns_ipv4: PID '2689' exit WITH ERROR '1' at 2017-02-10 21:12 Fri Feb 10 21:14:03 2017 authpriv.info dropbear[2980]: Child connection from 10.0.3.1:58973 Fri Feb 10 21:14:06 2017 authpriv.notice dropbear[2980]: Password auth succeeded for 'root' from 10.0.3.1:58973

aparcar commented 7 years ago

kpv:

Same system:

root@LEDE:~# cat /etc/modules.d/30-ipsec xfrm_algo xfrm_ipcomp xfrm_user af_key root@LEDE:~# cat /etc/modules.d/32-ipsec ah4 esp4 xfrm4_mode_beet xfrm4_mode_transport xfrm4_mode_tunnel xfrm4_tunnel ipcomp ah6 esp6 xfrm6_mode_beet xfrm6_mode_transport xfrm6_mode_tunnel xfrm6tunnel ipcomp6 root@LEDE:~# ls -la /lib/modules/4.9.8/xfrmko -rw-r--r-- 1 root root 5764 Feb 10 10:05 /lib/modules/4.9.8/xfrm_algo.ko -rw-r--r-- 1 root root 5340 Feb 10 10:05 /lib/modules/4.9.8/xfrm_ipcomp.ko -rw-r--r-- 1 root root 23348 Feb 10 10:05 /lib/modules/4.9.8/xfrm_user.ko root@LEDE:~#

aparcar commented 7 years ago

kpv:

Apparently *using insmod (instead of modprobe) loads the xfrm_ modules and thus ipsec (strongSwan) can start**:

root@LEDE:~# lsmod|fgrep xfrm tunnel4 1534 1 xfrm4_tunnel tunnel6 1534 1 xfrm6_tunnel xfrm4_mode_beet 1328 0 xfrm4_mode_transport 944 0 xfrm4_mode_tunnel 1328 0 xfrm4_tunnel 1328 0 xfrm6_mode_beet 1200 0 xfrm6_mode_transport 944 0 xfrm6_mode_tunnel 1200 0 xfrm6_tunnel 1923 0 root@LEDE:~# modprobe xfrm_algo failed to find a module named xfrm_algo root@LEDE:~# ls -la /lib/modules/4.9.8/xfrm_algo.ko -rw-r--r-- 1 root root 5764 Feb 10 10:05 /lib/modules/4.9.8/xfrm_algo.ko root@LEDE:~# md5sum /lib/modules/4.9.8/xfrm_algo.ko d074b75f463524f2aa8a0d51674a0104 /lib/modules/4.9.8/xfrmalgo.ko root@LEDE:~# ls -la /lib/modules/4.9.8/xfrm*ko -rw-r--r-- 1 root root 5764 Feb 10 10:05 /lib/modules/4.9.8/xfrm_algo.ko -rw-r--r-- 1 root root 5340 Feb 10 10:05 /lib/modules/4.9.8/xfrm_ipcomp.ko -rw-r--r-- 1 root root 23348 Feb 10 10:05 /lib/modules/4.9.8/xfrm_user.ko

root@LEDE:~# insmod /lib/modules/4.9.8/xfrm_algo.ko root@LEDE:~# insmod /lib/modules/4.9.8/xfrm_ipcomp.ko root@LEDE:~# insmod /lib/modules/4.9.8/xfrm_user.ko root@LEDE:~# lsmod|fgrep xfrm tunnel4 1534 1 xfrm4_tunnel tunnel6 1534 1 xfrm6_tunnel xfrm4_mode_beet 1328 0 xfrm4_mode_transport 944 0 xfrm4_mode_tunnel 1328 0 xfrm4_tunnel 1328 0 xfrm6_mode_beet 1200 0 xfrm6_mode_transport 944 0 xfrm6_mode_tunnel 1200 0 xfrm6_tunnel 1923 0 xfrm_algo 3541 2 xfrm_user,xfrm_ipcomp xfrm_ipcomp 2581 0 xfrm_user 16560 0 root@LEDE:~# root@LEDE:~# dmesg |tail [ 9.946070] kmodloader: - xfrm_user - 1 [ 13.430838] 8021q: adding VLAN 0 to HW filter on device eth0 [ 13.433278] br-lan: port 1(eth0) entered blocking state [ 13.435215] br-lan: port 1(eth0) entered disabled state [ 13.437368] device eth0 entered promiscuous mode [ 13.470226] br-lan: port 1(eth0) entered blocking state [ 13.472259] br-lan: port 1(eth0) entered forwarding state [ 13.514444] 8021q: adding VLAN 0 to HW filter on device eth1 [ 15.002555] random: crng init done [ 1119.235177] Initializing XFRM netlink socket root@LEDE:~#

root@LEDE:~# dmesg |tail [ 9.946070] kmodloader: - xfrm_user - 1 [ 13.430838] 8021q: adding VLAN 0 to HW filter on device eth0 [ 13.433278] br-lan: port 1(eth0) entered blocking state [ 13.435215] br-lan: port 1(eth0) entered disabled state [ 13.437368] device eth0 entered promiscuous mode [ 13.470226] br-lan: port 1(eth0) entered blocking state [ 13.472259] br-lan: port 1(eth0) entered forwarding state [ 13.514444] 8021q: adding VLAN 0 to HW filter on device eth1 [ 15.002555] random: crng init done [ 1119.235177] Initializing XFRM netlink socket root@LEDE:~# /etc/init.d/ipsec stop Stopping strongSwan IPsec failed: starter is not running root@LEDE:~# /etc/init.d/ipsec start no files found matching '/etc/strongswan.d/*.conf' Starting strongSwan 5.5.1 IPsec [starter]... root@LEDE:~# ps PID USER VSZ STAT COMMAND 1 root 1028 S /sbin/procd 2 root 0 SW [kthreadd] 3 root 0 SW [ksoftirqd/0] 4 root 0 SW [kworker/0:0] 5 root 0 SW< [kworker/0:0H] 6 root 0 SW [kworker/u2:0] 7 root 0 SW [rcu_sched] 8 root 0 SW [rcu_bh] 9 root 0 SW [migration/0] 10 root 0 SW< [lru-add-drain] 11 root 0 SW [cpuhp/0] 12 root 0 SW< [netns] 14 root 0 SW [oom_reaper] 353 root 0 SW< [writeback] 355 root 0 SW< [crypto] 356 root 0 SW< [bioset] 358 root 0 SW< [kblockd] 421 root 0 SW< [ata_sff] 533 root 0 SW [kworker/0:1] 547 root 0 SW [kswapd0] 548 root 0 SW< [vmstat] 627 root 0 SW< [pencrypt] 629 root 0 SW< [pdecrypt] 652 root 0 SW< [acpi_thermal_pm] 690 root 0 SW< [bioset] 693 root 0 SW< [bioset] 696 root 0 SW< [bioset] 699 root 0 SW< [bioset] 702 root 0 SW< [bioset] 705 root 0 SW< [bioset] 708 root 0 SW< [bioset] 711 root 0 SW< [bioset] 725 root 0 SW [scsi_eh_0] 726 root 0 SW< [scsi_tmf_0] 729 root 0 SW [scsi_eh_1] 739 root 0 SW< [scsi_tmf_1] 742 root 0 SW [scsi_eh_2] 743 root 0 SW< [scsi_tmf_2] 746 root 0 SW< [ipv6_addrconf] 747 root 0 SW [kworker/u2:3] 809 root 0 SW< [bioset] 813 root 0 SW< [bioset] 817 root 0 SW< [kworker/0:1H] 826 root 0 SW< [ext4-rsv-conver] 1069 root 780 S /sbin/ubusd 1076 root 660 S /sbin/askfirst /usr/libexec/login.sh 1499 root 0 SW< [cfg80211] 1622 root 884 S /sbin/logd -S 64 1670 root 1176 S /sbin/netifd 1710 root 984 S /usr/sbin/odhcpd 1757 root 852 S /usr/sbin/dropbear -F -P /var/run/dropbear.1.pid -p 22 -K 300 1900 root 740 S odhcp6c -s /lib/netifd/dhcpv6.script -P0 -t120 eth1 1901 root 972 S udhcpc -p /var/run/udhcpc-eth1.pid -s /lib/netifd/dhcp.script -f -t 0 -i eth1 -C -O 121 2103 root 976 S < /usr/sbin/ntpd -n -N -S /usr/sbin/ntpd-hotplug -p 0.lede.pool.ntp.org -p 1.lede.pool.ntp.org -p 2.lede.pool.ntp.org -p 3.lede.pool.ntp.org 2400 root 976 S {mwan3track} /bin/sh /usr/sbin/mwan3track wan eth1 2 1 2 5 3 8 208.67.220.220 208.67.222.222 8.8.8.8 8.8.4.4 2645 root 1812 S {dnsmasq} /sbin/ujail -n dnsmasq -u -l -r /dev/null -r /dev/urandom -r /etc/TZ -r /etc/dnsmasq.conf -r /etc/ethers -r /etc/group -r /etc/hosts -r /etc/passwd 2647 dnsmasq 1028 S /usr/sbin/dnsmasq -C /var/etc/dnsmasq.conf.cfg02411c -k -x /var/run/dnsmasq/dnsmasq.cfg02411c.pid 3373 root 920 S /usr/sbin/dropbear -F -P /var/run/dropbear.1.pid -p 22 -K 300 3380 root 980 S -ash 6382 root 1592 S /usr/lib/ipsec/starter --daemon charon 6383 root 4120 S /usr/lib/ipsec/charon --use-syslog 6412 root 972 S sleep 5 6418 root 972 R ps root@LEDE:~# root@LEDE:~# logread |tail -30 Sat Feb 11 19:23:57 2017 daemon.info dnsmasq[1]: using local addresses only for domain lan Sat Feb 11 19:23:57 2017 daemon.info dnsmasq[1]: reading /tmp/resolv.conf.auto Sat Feb 11 19:23:57 2017 daemon.info dnsmasq[1]: using local addresses only for domain lan Sat Feb 11 19:23:57 2017 daemon.info dnsmasq[1]: using nameserver 10.0.3.1#53 Sat Feb 11 19:23:57 2017 daemon.info dnsmasq[1]: read /etc/hosts - 4 addresses Sat Feb 11 19:23:57 2017 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg02411c - 2 addresses Sat Feb 11 19:23:57 2017 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses Sat Feb 11 19:23:58 2017 user.notice ddns-scripts[2682]: myddns_ipv4: PID '2682' started at 2017-02-11 19:23 Sat Feb 11 19:23:58 2017 user.warn ddns-scripts[2682]: myddns_ipv4: Service section disabled! - TERMINATE Sat Feb 11 19:23:58 2017 user.warn ddns-scripts[2682]: myddns_ipv4: PID '2682' exit WITH ERROR '1' at 2017-02-11 19:23 Sat Feb 11 19:24:38 2017 daemon.info dnsmasq[1]: read /etc/hosts - 4 addresses Sat Feb 11 19:24:38 2017 daemon.info dnsmasq[1]: read /tmp/hosts/dhcp.cfg02411c - 2 addresses Sat Feb 11 19:24:38 2017 daemon.info dnsmasq-dhcp[1]: read /etc/ethers - 0 addresses Sat Feb 11 19:27:29 2017 authpriv.info dropbear[3373]: Child connection from 10.0.3.1:33839 Sat Feb 11 19:27:32 2017 authpriv.notice dropbear[3373]: Password auth succeeded for 'root' from 10.0.3.1:33839 Sat Feb 11 19:42:18 2017 kern.info kernel: [ 1119.235177] Initializing XFRM netlink socket Sat Feb 11 19:44:30 2017 authpriv.info ipsec_starter[6362]: Starting strongSwan 5.5.1 IPsec [starter]... Sat Feb 11 19:44:30 2017 kern.info kernel: [ 1251.338997] NET: Registered protocol family 15 Sat Feb 11 19:44:30 2017 daemon.err modprobe: xfrm4_tunnel is already loaded Sat Feb 11 19:44:30 2017 daemon.err modprobe: xfrm_user is already loaded Sat Feb 11 19:44:31 2017 daemon.info : 00[DMN] Starting IKE charon daemon (strongSwan 5.5.1, Linux 4.9.8, i686) Sat Feb 11 19:44:31 2017 daemon.info : 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts' Sat Feb 11 19:44:31 2017 daemon.info : 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts' Sat Feb 11 19:44:31 2017 daemon.info : 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts' Sat Feb 11 19:44:31 2017 daemon.info : 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts' Sat Feb 11 19:44:31 2017 daemon.info : 00[CFG] loading crls from '/etc/ipsec.d/crls' Sat Feb 11 19:44:31 2017 daemon.info : 00[CFG] loading secrets from '/etc/ipsec.secrets' Sat Feb 11 19:44:31 2017 daemon.info : 00[LIB] loaded plugins: charon aes des rc2 sha2 sha1 md5 random nonce x509 revocation constraints pubkey pkcs1 pgp dnskey sshkey pem fips-prf gmp xcbc hmac attr kernel-netlink resolve socket-default connmark stroke updown xauth-generic Sat Feb 11 19:44:31 2017 daemon.info : 00[JOB] spawning 16 worker threads Sat Feb 11 19:44:31 2017 authpriv.info ipsec_starter[6382]: charon (6383) started after 40 ms root@LEDE:~#

aparcar commented 7 years ago

bjonglez:

This looks very similar to FS#443. yousong, do you have any idea?

aparcar commented 7 years ago

bjonglez:

KPapad, can you reproduce the issue with a 4.4 kernel?

aparcar commented 7 years ago

kpv:

Baptiste, I think Anton already did in FS#443:

Anton van Bohemen commented on 12.02.2017 18:22

I have been digging through the git rep of ubox, and I have built every version from the last 2 months until the version which is now referenced in the LEDE source.git. This is what I found (the date is the commit date):

ubox_2016-12-04-acc48b55-1_mips_24kc.ipk - xfrm_algo loads fine ubox_2016-12-19-db070f15-1_mips_24kc.ipk - xfrm_algo loads fine ubox_2016-12-19-8488bb5b-1_mips_24kc.ipk - xfrm_algo loads fine ubox_2017-01-15-eacc4261-1_mips_24kc.ipk - xfrm_algo loads fine ubox_2017-01-15-46a4b5f7-1_mips_24kc.ipk - xfrm_algo loads fine ubox_2017-01-15-a62c946e-1_mips_24kc.ipk - router failed to boot - needed failsafe and firstboot to get back. ubox_2017-01-15-93714117-1_mips_24kc.ipk - router failed to boot - needed failsafe and firstboot to get back. ubox_2017-01-15-6e3c6dcf-1_mips_24kc.ipk - "kmodloader: failed to find dependency xfrm_algo" ubox_2017-01-15-14839f0a-1_mips_24kc.ipk - "kmodloader: failed to find dependency xfrm_algo" ubox_2017-02-01-f8d3d167-1_mips_24kc.ipk - "kmodloader: failed to find dependency xfrm_algo" ubox_2017-02-01-ac2d43e7-1_mips_24kc.ipk - "kmodloader: failed to find dependency xfrm_algo"

So, the bug lies in one of three commits: a62c946ecdced9468ad16738325ee322029b0476 kmodloader: modprobe: skip possible command line arguments 9371411715c8dd882f1d65a712f1f38b6d38d01f kmodloader: fix out-of-bound access when parsing .modinfo 6e3c6dcf922e30282d2c49a643253e58fffab362 kmodloader: add module alias awareness

That is as close as I can get, I am not a debugger :) I just have some git knowlegde and I like to test LEDE.

aparcar commented 7 years ago

nbd:

Please try the latest version from my staging tree at https://git.lede-project.org/?p=lede/nbd/staging.git;a=summary

aparcar commented 7 years ago

kpv:

I'd like to happily report that with today's ubox upgrade, the kmodloader errors under LEDE trunk seem solved!