DHCP overriding my STATIC IP on wireless using Frisbee

[npierce]

Richard,

The other day I rebooted into Precise 5.7.1 and started to capture the pdiag*.tar.gz files that you requested for both the unmodified frisbee from Precise 5.7.1 and the version with my patch. But I ran into some confusion.

You said you were specifically interested in the dhcpcd.log and wpa_supplicant.log files. The problem was that the pdiag*.tar.gz files that were created had no dhcpcd.log, and only an empty wpa_supplicant.log.

Wondering what I was doing wrong, I looked into the matter and found a couple of unexpected things:

1. wpa_supplicant.log

Using wpa_supplicant v0.7.3 (that comes with Precise 5.7.1), I am unable to redirect stdout to a file using the following line:

Code: Select all

setsid wpa_supplicant -B -d -Dwext -iwlan0 -c/etc/frisbee/wpa_supplicant.conf > /tmp/wpa_supplicant.log

(Surprisingly I can redirect it to another tty, just not a file.)

On my hardware, the above line is the command sent by the start-wpa function in /usr/local/frisbee/func after it evaluates this line:

Code: Select all

setsid wpa_supplicant -B -d -Dwext -i$INTERFACE -c$WPACFGFILE > /tmp/wpa_supplicant.log

To redirect output to a file I needed to use wpa_supplicant's -f option, like so:

Code: Select all

setsid wpa_supplicant -B -d -Dwext -iwlan0 -c/etc/frisbee/wpa_supplicant.conf -f/tmp/wpa_supplicant.log

So in order to generate wpa_supplicant.log, I made that change to the appropriate two lines in this block of /usr/local/frisbee/func:

Code: Select all

	if grep -q '^wpa_log_mode=1' /etc/frisbee/frisbee.conf ; then
		setsid wpa_supplicant -B -d -Dwext -i$INTERFACE -c$WPACFGFILE -f/tmp/wpa_supplicant.log
	else
		setsid wpa_supplicant -B -Dwext -i$INTERFACE -c$WPACFGFILE -f/tmp/wpa_supplicant.log
	fi

Does frisbee generate a wpa_supplicant.log for you without that change? If so, are you using a different version of wpa_supplicant?

2. dhcpcd.log

Clicking the Generate Diagnostic Data in frisbee doesn't actually generate a dhcpcd.log file. Apparently that file is only generated when the user chooses the Network Interfaces tab and then clicks View DHCP Log. If the log file has already been generated, it will be grabbed by clicking Generate Diagnostic Data, but the log is only as recent as the last time the user clicked View DHCP Log, which could've been at the time of the last blue moon. This can be a bit confusing.

So in order to generate a current dhcpcd.log for you, I will click View DHCP Log just prior to clicking Generate Diagnostic Data. Of course, since that log file is just stuff extracted from /var/log/messages, dhcpcd.log is a bit redundant, since /var/log/messages is also included in the tar ball, but I'll include it for convenience.


I'll be sending you four pdiag*.tar.gz files:

1. Generated after clicking Save Profile, with my patch
2. Generated after stopping and starting /etc/init.d/frisbee, with my patch
3. Generated after clicking Save Profile, no patch
4. Generated after stopping and starting /etc/init.d/frisbee, no patch


So that you know what steps were taken before the files were created, here is my general procedure:

1. Boot Precise 5.7.1 with: "puppy pfix=ram".
2. Overwrite /etc/init.d/frisbee with my patched version.
3. Edit /usr/local/frisbee/func to use -f option when starting wpa_supplicant, as described above.
4. Start frisbee configuration script.
5. Click Diagnostics button.
6. Tick Enable Debug Logging check box.
7. Close "Wireless Diagnostic Tools" window.
8. Select access point from table.
9. Click Connect button.
10. Enter key and key type.
11. Wait for connection to be established.
12. Click Manage Saved Networks button.
13. Enter static ip address, subnet mask, gateway, DNS server.
14. Click Save Profile button.
15. Wait for connection to be established.
16. Click OK button under "Profile updated" message.
17. Close "Manage Saved Network Profiles" window.
18. Click Network Interfaces tab.
19. Click View DHCP Log button.
20. Close "DHCP Log" window.
21. Click Wireless Networks tab.
22. Click Diagnostics button.
23. Click Generate Diagnostic Data button.
24. Enter name.
25. Click No to not exclude WPA files.
26. Click OK to close "Pdialog Diagnostic Information Capture" window.
27. Close "Wireless Diagnostic Tools" window.
28. Click Exit button.
29. Enter these two commands:

    Code: Select all

    /etc/init.d/frisbee stop
    /etc/init.d/frisbee start

30. Wait for connection to be established.
31. Start frisbee configuration script.
32. Click Network Interfaces tab.
33. Click View DHCP Log button.
34. Close "DHCP Log" window.
35. Click Wireless Networks tab.
36. Click Diagnostics button.
37. Click Generate Diagnostic Data button.
38. Enter name.
39. Click No to not exclude WPA files.
40. Click OK to close "Pdialog Diagnostic Information Capture" window.
41. Close "Wireless Diagnostic Tools" window.
42. Click Exit button.

Repeat above but omit overwriting /etc/init.d/frisbee.


Don't be confused by the fact that the connection will first be made to a leased ip address when I click the Connect button, even though I want to use a static address. That's not the bug we are discussing in this thread. (That's more of a design flaw than a bug: I am unable to manage a profile and configure it to use a static address until the profile has been created; and I am unable to create a profile except by clicking the Connect button which automatically connects using a leased address, if available. So the cart is before the horse.)

The problem discussed in this thread happens after I restart the frisbee initialization script. With the unmodified script, a leased address is used, as indicated in the fourth pdiag*.tar.gz by these lines in pdiag-201401092052/network/dhcpcd.log:

Code: Select all

Jan  9 20:50:42 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: using hwaddr 00:13:02:3d:a2:fe
Jan  9 20:50:42 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks', reason PREINIT
Jan  9 20:50:42 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks', reason CARRIER
Jan  9 20:50:43 puppypc30828 daemon.info dhcpcd[25625]: wlan0: broadcasting for a lease
Jan  9 20:50:43 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: sending DISCOVER (xid 0x329d5c44), next in 4.64 seconds
Jan  9 20:50:43 puppypc30828 daemon.info dhcpcd[25625]: eth0: waiting for carrier
Jan  9 20:50:43 puppypc30828 daemon.info dhcpcd[25625]: wlan0: offered 192.168.1.21 from 192.168.1.1
Jan  9 20:50:43 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: sending REQUEST (xid 0x329d5c44), next in 4.56 seconds
Jan  9 20:50:43 puppypc30828 daemon.info dhcpcd[25625]: wlan0: acknowledged 192.168.1.21 from 192.168.1.1
Jan  9 20:50:43 puppypc30828 daemon.info dhcpcd[25625]: wlan0: checking for 192.168.1.21
Jan  9 20:50:43 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: sending ARP probe (1 of 3), next in 1.19 seconds
Jan  9 20:50:44 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: sending ARP probe (2 of 3), next in 1.68 seconds
Jan  9 20:50:45 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: sending ARP probe (3 of 3), next in 2.00 seconds
Jan  9 20:50:47 puppypc30828 daemon.info dhcpcd[25625]: wlan0: leased 192.168.1.21 for 86400 seconds
Jan  9 20:50:47 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: renew in 43200 seconds, rebind in 75600 seconds
Jan  9 20:50:47 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: adding IP address 192.168.1.21/24
Jan  9 20:50:47 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: adding route to 192.168.1.0/24
Jan  9 20:50:47 puppypc30828 daemon.debug dhcpcd[25625]: wlan0: adding default route via 192.168.1.1

With my patched version, the desired static address is used, as indicated in the second pdiag*.tar.gz by these lines in pdiag-201401091813/network/dhcpcd.log:

Code: Select all

Jan  9 18:11:56 puppypc3672 daemon.debug dhcpcd[26819]: wlan0: using hwaddr 00:13:02:3d:a2:fe
Jan  9 18:11:56 puppypc3672 daemon.debug dhcpcd[26819]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks', reason PREINIT
Jan  9 18:11:56 puppypc3672 daemon.debug dhcpcd[26819]: wlan0: executing `/lib/dhcpcd/dhcpcd-run-hooks', reason CARRIER
Jan  9 18:11:56 puppypc3672 daemon.info dhcpcd[26819]: wlan0: using static address 192.168.1.4
Jan  9 18:11:56 puppypc3672 daemon.debug dhcpcd[26819]: wlan0: adding IP address 192.168.1.4/24
Jan  9 18:11:56 puppypc3672 daemon.debug dhcpcd[26819]: wlan0: adding route to 192.168.1.0/24
Jan  9 18:11:56 puppypc3672 daemon.debug dhcpcd[26819]: wlan0: adding default route via 192.168.1.1

Do you have this problem when using a static IP address? If so, does my patch work for you?

OK, now I'll go send you a PM with the four files. I hope this is helpful to you.

Norm

[npierce]

I had a chance to look at this some more.

. . . I am using a less than ideal test to determine when the scan is complete. I am waiting for a status line that says "wpa_state=COMPLETED". Doing that may not be reliable, since I've found no documentation that guarantees that that exact line is always issued, nor have I dug into the source code to verify that that is the case. Perhaps different hardware and a different wireless driver will cause a different message to be issued. Perhaps not.

I feel better about this test now. While I'm not sure if it is bullet-proof, I did dig into the source code and verified that it is always issued when a connection is made, and the text does not vary for different drivers. (See the wpa_supplicant_state_txt() function defined in wpa_supplicant-0.7.3/wpa_supplicant/wpa_supplicant.c in the source code, which can be found at http://archive.ubuntu.com/ubuntu/pool/m ... rig.tar.gz).

I previously misunderstood the meaning of the "COMPLETED" status. Since that status appears after the scan is completed, I assumed that it indicated that the scan was completed. But since it really means that the association and authentication (if any) of the connection has been completed, the "COMPLETED" status will never appear unless a connection has been made. So in the case where no connection has been completed, like on the first boot of a new Puppy, my test waited the full 33 seconds for a "COMPLETED" status that never came. This means that my code added an unnecessary delay to the frisbee configuration script the first time it was run.

So I've modified my code to also stop waiting if it sees a status line that says "wpa_state=INACTIVE", which is the status after the scan is complete when no connection has been made.

Both the "COMPLETED" and the "INACTIVE" state are documented in the source code:

Code: Select all

        /**
         * WPA_INACTIVE - Inactive state (wpa_supplicant disabled)
         *
         * This state is entered if there are no enabled networks in the
         * configuration. wpa_supplicant is not trying to associate with a new
         * network and external interaction (e.g., ctrl_iface call to add or
         * enable a network) is needed to start association.
         */
        WPA_INACTIVE,

Code: Select all

        /**
         * WPA_COMPLETED - All authentication completed
         *
         * This state is entered when the full authentication process is
         * completed. In case of WPA2, this happens when the 4-Way Handshake is
         * successfully completed. With WPA, this state is entered after the
         * Group Key Handshake; with IEEE 802.1X (non-WPA) connection is
         * completed after dynamic keys are received (or if not used, after
         * the EAP authentication has been completed). With static WEP keys and
         * plaintext connections, this state is entered when an association
         * has been completed.
         *
         * This state indicates that the supplicant has completed its
         * processing for the association phase and that data connection is
         * fully configured.
         */
        WPA_COMPLETED

Also, I have removed the ampersand from the call to the start-wpa function so that it is run in the foreground and the script will wait for the function to complete. It makes no sense to try to talk to wpa_supplicant until it has been started, and experimentation has show that the first attempt to do so was simply failing to connect to wpa_supplicant. Now no attempt is made until after it has started.


I will attach my revised version to my earlier (2013-Dec-17) post, where it will replace my initial version. I welcome feedback from anyone volunteering to try this out. While I am most interested to know if it solves the problem with static addressing, I also need to know if it causes any new problems for static or DHCP addressing. And if it causes no problems, feel free to report that as well -- I need to see some reports before recommending that this fix be included in new Puppies. Thanks.

[HoerMirAuf]

Thanks a lot for your fix!

I solved my static IP Problem on Precise-5.7.1

[npierce]

You're welcome. Thanks for trying out the fix. It is always good to know that my fixes actually work for people other than me before I recommend that they be added to future Puppies. So feedback like yours is very helpful.

[ahoppin]

This patch is working nicely for me on frugal Retro Precise 5.7.1, EEE PC 901. Well done!

If you're using Frisbee and Retro Precise 5.7.1, you may want to also view this thread:

http://murga-linux.com/puppy/viewtopic.php?p=838802