1. This site uses cookies. By continuing to use this site, you are agreeing to our use of cookies. Learn More.

Error with USB+VPN latest build 44

Discussion in 'Tomato Firmware' started by fredch, Feb 17, 2010.

  1. fredch

    fredch Addicted to LI Member

    Hello, i've upgraded from version 1.25.8634 vpn3.4 USB+VPN to the latest build 44.

    I have 2 VPN defined: a server that is working fine and a client that was working in the previous version (didn't change the config) it's based on TUN/UDP.

    Every time i attempt to manually start the client i've got the following error in the log :
    user.info init[1]: VPN_LOG_ERROR: 315: Starting OpenVPN failed...

    For info, the working server is configured as TAP/TCP.

    ssh to the router, i can see config for the server in /tmp/etc/openvpn, but nothing for the client.
     
  2. teddy_bear

    teddy_bear Network Guru Member

    fredch,
    I won't know anything about the VPN stuff, it's merely included...

    Look at the nvram variables for VPN: "nvram find vpn". If they look ok, I don't know what might be wrong. Check on the VPN thread if this is something that can happen when upgrading from vpn3.4 to vpn3.6, and/or what could possibly cause this. Let me know if you find out anything.
     
  3. Disman_ca

    Disman_ca Super Moderator Staff Member Member

    Forked out to seperat thread
     
  4. SgtPepperKSU

    SgtPepperKSU Network Guru Member

    That error message means that everything was set up properly; then the actual starting of the OpenVPN process returned bad status. This is not something I've heard of from users upgrading to TomatoVPN 1.27vpn3.6. Is there anything in the log from OpenVPN itself prior to that? If the OpenVPN configuration is invalid, it should state what was wrong.

    Setting the nvram variable vpn_debug to 2 will have it log more information (though, this is just for the GUI backend - not for OpenVPN itself). Setting it to higher than 2 will cause it to not delete the configuration files when cleaning up (like after OpenVPN fails to start) so you can inspect them.

    I have to ask: Did you perform a (thorough) NVRAM erase after your upgrade? There's nothing specific about the VPN changes that would need it, but "weird" things seem to happen occasionally after Tomato upgrades. An NVSRAM erase should clear them up. I suspect the NVRAM implementation is not very tolerant to different sizes of firmware being loaded.
     
  5. fredch

    fredch Addicted to LI Member

    OK i did set vpn_debug to 2, with the following result:

    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_INFO: 44: VPN GUI client backend starting...
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 151: Writing config file
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 254: Done writing config file
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 257: Writing certs/keys
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 307: Done writing certs/keys
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_INFO: 311: Starting OpenVPN: /etc/openvpn/vpnclient1 --cd /etc/openvpn/client1 --config config.ovpn
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_ERROR: 315: Starting OpenVPN failed...
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_INFO: 378: Stopping VPN GUI client backend.
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 381: Removing cron job
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 388: Done removing cron job
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 391: Removing firewall rules.
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 404: Done removing firewall rules.
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 407: Stopping OpenVPN client.
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 410: OpenVPN client stopped.
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 413: Removing VPN device.
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 421: VPN device removed.
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 442: Killing OpenVPN client.
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_EXTRA: 445: OpenVPN client killed.
    Feb 17 19:08:53 router user.info init[1]: VPN_LOG_INFO: 447: VPN GUI client backend stopped.

    then i've seen your message and set vpn_debug to 3 to try to start manually, and here is the openvpn log :
    Wed Feb 17 19:16:28 2010 OpenVPN 2.1.1 mipsel-unknown-linux-gnu [SSL] [LZO2] built on Feb 15 2010
    Wed Feb 17 19:16:28 2010 WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
    Wed Feb 17 19:16:28 2010 NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
    Wed Feb 17 19:16:28 2010 LZO compression initialized
    Wed Feb 17 19:16:28 2010 Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
    Wed Feb 17 19:16:28 2010 Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
    Wed Feb 17 19:16:28 2010 Socket Buffers: R=[108544->131072] S=[108544->131072]
    Wed Feb 17 19:16:28 2010 UDPv4 link local: [undef]
    Wed Feb 17 19:16:28 2010 UDPv4 link remote: xx.xx.196.125:443
    Wed Feb 17 19:16:28 2010 TLS: Initial packet from xx.xx.196.125:443, sid=0a645ab6 75a7b2ef
    Wed Feb 17 19:16:29 2010 VERIFY OK: depth=1, /C=US/ST=CA/L=dasfsdafsdfsd/O=OpenVPN/CN=fredch/Email=mail@host.domain
    Wed Feb 17 19:16:29 2010 VERIFY OK: depth=0, /C=US/ST=CA/O=dfdfsd/CN=server/Email=mail@host.domain
    Wed Feb 17 19:16:30 2010 Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
    Wed Feb 17 19:16:30 2010 Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    Wed Feb 17 19:16:30 2010 Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
    Wed Feb 17 19:16:30 2010 Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    Wed Feb 17 19:16:30 2010 Control Channel: TLSv1, cipher TLSv1/SSLv3 EDH-RSA-DES-CBC3-SHA, 1024 bit RSA
    Wed Feb 17 19:16:30 2010 [server] Peer Connection Initiated with xx.xx.196.125:443
    Wed Feb 17 19:16:32 2010 SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
    Wed Feb 17 19:16:32 2010 PUSH: Received control message: 'PUSH_REPLY,route 192.168.12.0 255.255.255.0,route 10.8.0.1,topology net30,ping 15,ping-restart 60,ifconfig 10.8.0.6 10.8.0.5'
    Wed Feb 17 19:16:32 2010 OPTIONS IMPORT: timers and/or timeouts modified
    Wed Feb 17 19:16:32 2010 OPTIONS IMPORT: --ifconfig/up options modified
    Wed Feb 17 19:16:32 2010 OPTIONS IMPORT: route options modified
    Wed Feb 17 19:16:32 2010 Note: Cannot ioctl TUNSETIFF tun11: Device or resource busy (errno=16)
    Wed Feb 17 19:16:32 2010 Note: Attempting fallback to kernel 2.2 TUN/TAP interface
    Wed Feb 17 19:16:32 2010 Cannot open TUN/TAP dev /dev/tun11: No such file or directory (errno=2)
    Wed Feb 17 19:16:32 2010 Exiting


    And finally, i did not do a NVRAM erase after the upgrade, but all the NVRAM key for the VPN looks fine.
     
  6. fredch

    fredch Addicted to LI Member

    Now i've erazed the NVRAM and then reloded the config, the behaviour is a little bit different :

    Pressing the start button on the interface still lead to the same kind of failure :

    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_INFO: 44: VPN GUI client backend starting...
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 151: Writing config file
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 254: Done writing config file
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 257: Writing certs/keys
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 307: Done writing certs/keys
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_INFO: 311: Starting OpenVPN: /etc/openvpn/vpnclient1 --cd /etc/openvpn/client1 --config config.ovpn
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_ERROR: 315: Starting OpenVPN failed...
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_INFO: 378: Stopping VPN GUI client backend.
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 381: Removing cron job
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 388: Done removing cron job
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 391: Removing firewall rules.
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 404: Done removing firewall rules.
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 407: Stopping OpenVPN client.
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 410: OpenVPN client stopped.
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 413: Removing VPN device.
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 421: VPN device removed.
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 442: Killing OpenVPN client.
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_EXTRA: 445: OpenVPN client killed.
    Feb 17 20:56:35 router user.info init[1]: VPN_LOG_INFO: 447: VPN GUI client backend stopped.

    But launching the same command (ie:/etc/openvpn/vpnclient1 --cd /etc/openvpn/client1 --config config.ovpn ) manually works (without changing any thing in the config files):

    Feb 17 20:57:28 router daemon.notice openvpn[807]: OpenVPN 2.1.1 mipsel-unknown-linux-gnu [SSL] [LZO2] built on Feb 15 2010
    Feb 17 20:57:28 router daemon.warn openvpn[807]: WARNING: No server certificate verification method has been enabled. See http://openvpn.net/howto.html#mitm for more info.
    Feb 17 20:57:28 router daemon.warn openvpn[807]: NOTE: OpenVPN 2.1 requires '--script-security 2' or higher to call user-defined scripts or executables
    Feb 17 20:57:28 router daemon.notice openvpn[807]: LZO compression initialized
    Feb 17 20:57:28 router daemon.notice openvpn[807]: Control Channel MTU parms [ L:1542 D:138 EF:38 EB:0 ET:0 EL:0 ]
    Feb 17 20:57:28 router daemon.notice openvpn[807]: Data Channel MTU parms [ L:1542 D:1450 EF:42 EB:135 ET:0 EL:0 AF:3/1 ]
    Feb 17 20:57:28 router daemon.notice openvpn[809]: Socket Buffers: R=[108544->131072] S=[108544->131072]
    Feb 17 20:57:28 router daemon.notice openvpn[809]: UDPv4 link local: [undef]
    Feb 17 20:57:28 router daemon.notice openvpn[809]: UDPv4 link remote: 217.79.196.125:443
    Feb 17 20:57:28 router daemon.notice openvpn[809]: TLS: Initial packet from xx.xx.196.125:443, sid=e07a9a76 d3760ce4
    Feb 17 20:57:29 router daemon.notice openvpn[809]: VERIFY OK: depth=1, /C=US/ST=CA/L=cxy<cxycyx=OpenVPN/CN=fredch/Email=mail@host.domain
    Feb 17 20:57:29 router daemon.notice openvpn[809]: VERIFY OK: depth=0, /C=US/ST=CA/O=ycx<cyx=server/Email=mail@host.domain
    Feb 17 20:57:31 router daemon.notice openvpn[809]: Data Channel Encrypt: Cipher 'BF-CBC' initialized with 128 bit key
    Feb 17 20:57:31 router daemon.notice openvpn[809]: Data Channel Encrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    Feb 17 20:57:31 router daemon.notice openvpn[809]: Data Channel Decrypt: Cipher 'BF-CBC' initialized with 128 bit key
    Feb 17 20:57:31 router daemon.notice openvpn[809]: Data Channel Decrypt: Using 160 bit message hash 'SHA1' for HMAC authentication
    Feb 17 20:57:31 router daemon.notice openvpn[809]: Control Channel: TLSv1, cipher TLSv1/SSLv3 EDH-RSA-DES-CBC3-SHA, 1024 bit RSA
    Feb 17 20:57:31 router daemon.notice openvpn[809]: [server] Peer Connection Initiated with xx.xx.196.125:443
    Feb 17 20:57:33 router daemon.notice openvpn[809]: SENT CONTROL [server]: 'PUSH_REQUEST' (status=1)
    Feb 17 20:57:33 router daemon.notice openvpn[809]: PUSH: Received control message: 'PUSH_REPLY,route 192.168.12.0 255.255.255.0,route 10.8.0.1,topology net30,ping 15,ping-restart 60,ifconfig 10.8.0.6 10.8.0.5'
    Feb 17 20:57:33 router daemon.notice openvpn[809]: OPTIONS IMPORT: timers and/or timeouts modified
    Feb 17 20:57:33 router daemon.notice openvpn[809]: OPTIONS IMPORT: --ifconfig/up options modified
    Feb 17 20:57:33 router daemon.notice openvpn[809]: OPTIONS IMPORT: route options modified
    Feb 17 20:57:33 router daemon.notice openvpn[809]: TUN/TAP device tun11 opened
    Feb 17 20:57:33 router daemon.notice openvpn[809]: TUN/TAP TX queue length set to 100
    Feb 17 20:57:33 router daemon.notice openvpn[809]: /sbin/ifconfig tun11 10.8.0.6 pointopoint 10.8.0.5 mtu 1500
    Feb 17 20:57:33 router daemon.notice openvpn[809]: /sbin/route add -net 192.168.12.0 netmask 255.255.255.0 gw 10.8.0.5
    Feb 17 20:57:33 router daemon.notice openvpn[809]: /sbin/route add -net 10.8.0.1 netmask 255.255.255.255 gw 10.8.0.5
    Feb 17 20:57:33 router daemon.notice openvpn[809]: Initialization Sequence Completed
     
  7. SgtPepperKSU

    SgtPepperKSU Network Guru Member

    Please do and reconfigure from scratch (don't restore backed up configuration file).

    I'd say 99% of the "now, that's just not how it's supposed to work" problems are fixed by doing so.

    I don't know what gets out of whack on some upgrades, but erasing NVRAM and reconfiguring it exactly the same seems to fix it.
     
  8. SgtPepperKSU

    SgtPepperKSU Network Guru Member

    Strange. You shouldn't have been able to start OpenVPN by just running that command. The TUN device shouldn't exist. Perhaps the GUI backend couldn't remove the device due to the same thing that kept it from starting OpenVPN. This could be caused by not being able to fork or execvp failing. I don't know why those would fail, but it could be related to the updated kernel in teddy_bear's builds.

    How much free memory do you have? Does this only happen when the server is running, or all of the time?
     
  9. fredch

    fredch Addicted to LI Member

    Not on the memory side :
    Total / Free Memory 29.93 MB / 13.71 MB (45.82%)

    it happen regardless of the server running or not. (server is TAP/TCP while the client is TUN/UDP)


    nvram variable vpn_debug set to 3, to keep the config files, does this also keep the TUN device ?
     
  10. SgtPepperKSU

    SgtPepperKSU Network Guru Member

    Then I don't know. The GUI backend is making system calls, and they aren't running. I don't know enough about teddy_bear's changes to know what could be different.
    Nope, it still tries to remove the TUN device (and cron entries, firewall rules, etc). It just doesn't delete any of the files so people can see what the configuration looked like.
     
  11. teddy_bear

    teddy_bear Network Guru Member

    fredch,
    I'm not sure what could cause fork to fail - especially since it's working for the server but not for the client :confused:.

    After vpn fails to start, can you execute the same command - "/etc/openvpn/vpnclient1 --cd /etc/openvpn/client1 --config config.ovpn" - successfully from the GUI Tools->System page as well as from telnet session, or it only works in telnet session?

    Does OpenVPN creates any log when it fails to start?

    If you guys can tell me what I need to enter to configure a VPN client to test it, I'll try that...
     
  12. SgtPepperKSU

    SgtPepperKSU Network Guru Member

    Yes, it should have at least several lines in the log (as long as it gets far enough to read the "daemon" line in the config file, but I don't think it's a problem of not being able to read that file) when it fails to start, detailing the reason it failed. The fact that it doesn't show anything and _eval returns non-zero leads me to think it's never being run at all.

    UPDATE:
    I'm pretty sure I see the problem. The array used to pass the parameters to _eval is one too small for the client. This would make it possible for the parameter list to become unterminated (the NULL arg could be overwritten by whatever actually owns that memory, or differences in memory management in your kernel cause it to never be set to NULL since I don't own it), causing it to not parse correctly. I can't believe that bug has been there for a long time without causing any problems (or me noticing it).

    Since it isn't causing a problem in my builds, for whatever reason, I'll wait until my next release to fix it in my builds. If you want to update yours, the 5 on line 36 of router/rc/vpn.c needs to be a 6.
     
  13. teddy_bear

    teddy_bear Network Guru Member

    Thanks! It only took an updated kernel for the bug to reveal itself ;).

    I'll post an updated USB+VPN build tonight - hopefully it will fix the issue.
     
  14. teddy_bear

    teddy_bear Network Guru Member

    fredch,
    I updated the VPN build with the fix proposed by SgtPepperKSU. Could you re-download it, and let us know if it works properly now?
     
  15. fredch

    fredch Addicted to LI Member

    SgtPepperKSU and teddy_bear,

    Thanks a lot for your quick and effective support, you nailed it, array too small.

    The new build is starting the client automatically and it can also be started/stopped it from the GUI.
     
  16. bub181

    bub181 Addicted to LI Member

    Hi teddy_bear,
    Could you please tell me what the time stamp on the updated binary is? The one I downloaded has a time stamp of: 17 Feb. 18:31.
    Thanks!
     
  17. contrary

    contrary Addicted to LI Member

    Vpn_log_error

    Greetings!
    Firstly, big thanks to Teddy_Bear and everyone else who have worked so hard to weed this garden as I have lurked. I know only enough linux to be dangerous.

    I have an Asus WL-500g Premium v2 (and an RT-N16 in the mail) that I have been playing with, configured to connect to a commercial vpn account and that has worked well up to v43 while I played with USB stuff and tried to get my arms around optware and linux.

    I think my recent experience might be instructive, and give me a rare chance to contribute. After I downloaded and flashed tomato-NDUSB-8743vpn3.6-VPN.trx yesterday, erased NVRAM thoroughly, and reconfigured vpn Client1 from scratch using the excellent GUI, pressing the 'Start' button did not start the vpn. Looking in the log I saw the same error noted in this thread

    VPN_LOG_ERROR: 316:
    Googling this error took me to Moyers's source code - The last time I tried programming anything serious it was in integer BASIC.

    So I checked again, retried v42 (which worked), and basically ran around in circles a while. So then at some point I voided the Teddy_Bear warrantee and just flashed v42 onto v43 withOUT erasing NVRAM. This worked!! That was cool, so for my next stunt I flashed SgtPepper's tomatovpn-ND-1.27vpn-3.6 on top of your v42. My thought was that the only vpn-difference between v42 and v43 was SgtPepper's and Openvpn's updates: reading the changelogs for these looked like these were mostly bugfixes, and I had a sporting chance since by this time I was only fooling with the vpn/Client1 config. That worked as well... so to summarize:

    Teddy_Bear v42 sets up a client1 vpn to my commercial vpn proxy service on demand, no problems
    ! Teddy_Bear v43 reports VPN_LOG_ERROR, but
    !! Teddy_Bear v42 works with the UNerased NVRAM configured by hand in v43 (not to be recommended)
    !!! SgtPepper vpn3.6 works with the same UNerased NVRAM configured by hand in v43 (totally not to be recommended. The Standard Disclaimer Applies.)

    So it appeared to me the server was not starting because something was moved and ovpn couldn't find it in v43. A friend of mine also reported the same symptoms using a WRT54-TM and another vpn server using TLS. So my conclusion was that contrary to logic, the problem was in v43 - I realize the vpn stuff is not the original intent in this build.

    So my contribution here is to note that sometimes you can learn something by consciously disobeying. I also touch Wet Paint! to see if it's dry yet....

    It's good to see this issue resolved so fast and I will move on to the fixed version, and to my shiney new N16. Thanks for the troubleshooting recommendations in this thread which I have noted, and thanks in advance for more rapid repairs in the future.
     
  18. teddy_bear

    teddy_bear Network Guru Member

    bub181,
    That's the correct build.
     

Share This Page