Interaction between connectToService/sendStartAdhocCommand and disconnectFromService/sendStopAdhocCommand about android-manet-manager

[jrobble]

To be honest, I haven't done many tests that involve programmatically stopping the MANET after it's started, so what you found is probably a bug.

ManetHelper.connectToService() serves two purposes. First, it starts the service if it isn't already stared, and second it creates a receiveMessenger that's used to receive info from the service, such as query responses.

[duhmojo]

Funny, I was looking at handling it the same from my app but I'm in the middle of a re-factor and haven't tested it yet. There is the un-used ManetCustomBroadcastReceiver.java, but its not registered with anything. jrobble, was it part of an unrealized design idea?

[daviddoria]

So it seems like if I call
manetHelper.sendStartAdhocCommand();
it works even when the service is not started.

However, the call to
manetHelper.sendAdhocStatusQuery();

only works when the service is started. Are these things fundamentally different like this? I.e. would you guys expect this to be the behavior?

[daviddoria]

The "Receiver not registered: null" exception only happens when I try to disconnectFromService() twice in a row. The only reason I tried to do it twice is because manetHelper.isConnectedToService() continues to return true even after disconnectFromService() is called.

I see two options:
1)
sendMessenger = null;
to disconnectFromService() (this is done in onServiceDisconnected, so it seems like the right thing to do). This needs to be done because isConnectedToService() simply returns sendMessenger != null;

2. We could do something painful (and according to StackOverflow seems to be the only way to check if a receiver is registered) like this:
   // If the receiver can be successfully unregistered, that means it was registered (and we have to re-register it)
   public boolean isConnectedToService() {
   boolean wasRegistered = true;
   try{
   context.unregisterReceiver(intentReceiver);
   }
   catch (Exception e) {
   wasRegistered = false;
   }

if(wasRegistered){
context.registerReceiver(intentReceiver, intentFilter);
}
}

[jrobble]

@duhmojo - Yeah, ManetCustomBroadcastReceiver isn't used. The original idea was that it would start the service, but now you can use the ManetHelper to do that.

[jrobble]

@daviddoria - Are you sure the service isn't started? Through a chain of events the MANET Manager will invoke ManetHelper.connectToService() when the main activity is first created. Look at MainActivity.onEulaAccepted().

[jrobble]

@daviddoria - In regards to the two options you present above, I like 1) better. It's clean and simple.

[daviddoria]

@jrobble But I am not opening the MANET Manager, I am just calling manetHelper.connectToService() .

@jrobble Ok, it is just a bit more internal-stateful.

[jrobble]

manetHelper.connectToService() will start the service, which is why manetHelper.sendStartAdhocCommand() will work. manetHelper.connectToService() uses this code:

// to start a Service or Activity in another package, use setComponent()
Intent i = new Intent().setComponent(new ComponentName("org.span", "org.span.service.core.ManetService"));
context.startService(i);

I do this so that the service starts as soon as anybody tries to connect to it. Note that nothing bad will happen if the service is already started and that code is executed again.

[duhmojo]

Sorry, did anyone conclude what the best way to stop Manet Manager from a 3rd party app? A common case I expect, and am dealing with, is if the 3rd party app (mine) needs to perform a wifi scan or otherwise, you need to turn wifi in the Android OS on. So if you're in a MANET, you need to tell Manet Manager to stop, then turn wifi on, (Manet Manager needs wifi off to work, I've had it get into funky states depending) performance your scan (onRecieve will not fire unless Android believes wifi is on), then put to all back, assuming you want to revert to a MANET working state. e.g. stop wifi, start Manet Manager.

[jrobble]

Right. The Manet Manager completely takes over control of the Wi-Fi and tells the Android framework that there's no Wi-Fi connection to prevent it from messing with what the Manet Manger is doing under the hood.

Your third party app will need to turn ad-hoc mode off. You can do this by invoking sendStopAdhocCommand() on the ManetHelper. I think we resolved the null pointer issue @daviddoria mentions above.

[duhmojo]

Basically in my Service onCreate I register the helper:

manetManager = new ManetManagerObserver();
manetHelper = new ManetHelper(this);
manetHelper.registerObserver(manetManager);
manetHelper.connectToService();

With my app running, if ManetManager is started I'll get a log entry for state changed. e.g. started.

I then try determining the current state of MM by calling manetHelper.sendAdhocStatusQuery(), which doesn't result in anything in the Observer getting fired.

If ManetManager is already running, but the manet isn't enabled, when I manually turn it on the Observer will fire onAdhocStateUpdated(). However its difficult to tell from my App/Service if MM is actually running a manet.

Doesn't matter if MM has the manet enabled or not (manually), when I try calling sendStartAdhocCommand(), I get the following NullPointer:

10-10 23:13:19.429: W/System.err(2824): java.lang.NullPointerException
10-10 23:13:19.429: W/System.err(2824): at org.span.service.ManetHelper.sendMessage(ManetHelper.java:184)
10-10 23:13:19.429: W/System.err(2824): at org.span.service.ManetHelper.sendAdhocStatusQuery(ManetHelper.java:165)
10-10 23:13:19.437: W/System.err(2824): at com.drdc.test.testm.comm.CommService.onCreate(CommService.java:193)
10-10 23:13:19.437: W/System.err(2824): at android.app.ActivityThread.handleCreateService(ActivityThread.java:1945)
10-10 23:13:19.437: W/System.err(2824): at android.app.ActivityThread.access$2500(ActivityThread.java:117)
10-10 23:13:19.445: W/System.err(2824): at android.app.ActivityThread$H.handleMessage(ActivityThread.java:985)
10-10 23:13:19.453: W/System.err(2824): at android.os.Handler.dispatchMessage(Handler.java:99)
10-10 23:13:19.460: W/System.err(2824): at android.os.Looper.loop(Looper.java:130)
10-10 23:13:19.460: W/System.err(2824): at android.app.ActivityThread.main(ActivityThread.java:3683)
10-10 23:13:19.460: W/System.err(2824): at java.lang.reflect.Method.invokeNative(Native Method)
10-10 23:13:19.460: W/System.err(2824): at java.lang.reflect.Method.invoke(Method.java:507)
10-10 23:13:19.460: W/System.err(2824): at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:839)
10-10 23:13:19.460: W/System.err(2824): at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:597)
10-10 23:13:19.468: W/System.err(2824): at dalvik.system.NativeStart.main(Native Method)

At this point MM is in a funky state. If I flip back to MM, the manet is disabled, but if I try to manually enable it it will fail to do so. I have to restart the device to get it back to a working state. (that is so MM can enable the manet again)

Further to this point, I tried reboot, starting MM, starting the manet, Then from my app, only registering, connecting and stopping the manet. i get another NullPointerException like above. HOWEVER, if I flip back to MM the manet appears to be alive. If I manually stop it, then start it again, it'll fail to start and I need to reboot the device again. The org.span logs don't highlight any failure:

10-10 23:24:39.851: D/MainActivity(1442): StartBtn pressed ...
10-10 23:24:39.851: D/MainActivity(1442): onCreateDialog()
10-10 23:24:39.875: D/CoreTask(1466): Root command ==> /data/data/org.span/bin/adhoc start 1
10-10 23:24:41.640: D/MainActivity(1442): Temp ==> 340 -- Celsius ==> 34 -- Fahrenheit ==> 93
10-10 23:24:44.179: D/dalvikvm(1466): GC_CONCURRENT freed 514K, 58% free 2855K/6727K, external 1625K/2137K, paused 3ms+3ms
10-10 23:24:46.242: D/dalvikvm(1466): GC_CONCURRENT freed 585K, 58% free 2865K/6727K, external 1625K/2137K, paused 2ms+2ms
10-10 23:24:46.304: D/dalvikvm(1466): GC_CONCURRENT freed 583K, 58% free 2874K/6727K, external 1625K/2137K, paused 2ms+2ms
10-10 23:24:46.359: D/dalvikvm(1466): GC_CONCURRENT freed 614K, 58% free 2859K/6727K, external 1625K/2137K, paused 2ms+3ms
10-10 23:24:46.414: D/dalvikvm(1466): GC_CONCURRENT freed 596K, 58% free 2852K/6727K, external 1625K/2137K, paused 3ms+3ms
10-10 23:24:46.445: D/MainActivity(1442): onAdhocStateUpdated()
10-10 23:24:46.445: D/MainActivity(1442): removeDialog()
10-10 23:24:46.453: D/ManetManagerApp(1442): onAdhocStateUpdated()
10-10 23:24:46.460: D/ManetServiceHelper(1466): Alarm activated!
10-10 23:24:46.468: D/ManetManagerApp(1466): onAdhocStateUpdated()
10-10 23:24:46.468: D/ManetServiceHelper(1466): Alarm activated!
10-10 23:24:46.476: D/ManetServiceHelper(1466): Alarm activated!

Any clues? I can continue my work ignoring MM for now and manually controlling it, but the Observer and Helper don't seem to be firing as expected and depending on how someone intends to integrate with MM, an Observer needs to be reliable. For example, if I have an AsyncTask or Runnable that has to query MM's state before moving forward/blocking, I need to send the query, then wait for a response, in a wait/timeout loop until I get it.

I tried to solve this by registering/connecting/querying up front, then later when that task is called, I should know if the manet is up and running.already. This doesn't seem to be working for me though.

Thanks for the great work.

[jrobble]

"I then try determining the current state of MM by calling manetHelper.sendAdhocStatusQuery(), which doesn't result in anything in the Observer getting fired."

It should result in onAdhocStateUpdated() being fired. Note that the service won't broadcast the ACTION_ADHOC_STATE_UPDATED intent to everyone, rather it handles queries by replying directly to the app that issued the query. See IncomingHandler.handleMessage() in ManetHepler. The QUERY_ADHOC_STATUS case should be executed. Try using Eclipse to debug the call chain.

"If ManetManager is already running, but the manet isn't enabled, when I manually turn it on the Observer will fire onAdhocStateUpdated(). However its difficult to tell from my App/Service if MM is actually running a manet."

I use manetHelper.sendAdhocStatusQuery() to tell if the the manet is actually running at any given point in time.

"Doesn't matter if MM has the manet enabled or not (manually), when I try calling sendStartAdhocCommand(), I get the following NullPointer:"

Looking at the line numbers in the exception, it doesn't seem like you're using the newest version of the Manet service code where @daviddoria added a Logcat error message for this issue. You need to recompile the Manet Manager code, run the create-lib.sh script to regenerate libmanet.jar, and then copy that library into your third party app. Here's the script:

https://github.com/ProjectSPAN/android-manet-manager/blob/master/AndroidManetManager/scripts/create-lib.sh

Looking at the old code, I see your exception blows up on the "sendMessenger.send(message);" line. This is most likely because sendMessenger is null. You'll see that sendMessenger is initialized in ManetServiceConnection.onServiceConnected(). Thus, I'm led to believe that your third party app is not properly connecting to the Manet service for some reason.

Note that we haven't implemented a monitor in the Manet Manager yet, so if for some reason the manet goes down, the device drops out of ad-hoc mode, or the routing protocol process is killed, the Manet Manager will not know about it unless the Manet Manger is responsible for the change. It would be useful if the Manet service spawned a thread that periodically checks for these things and notifies registered observers when things change.

[duhmojo]

Ok, I've made some great progress but I have a real thread blocking issue with the Helper/Observer pattern that is making this difficult to work with. First, I updated my ManetManager source, built it, exported the required libmanet.jar classes into a new jar, then imported that into my app's project. In my Service onCreate() (maybe not the best place to put it, but its there for now) I have the following:

manetHelper = new ManetHelper(this);
manetManager = new ManetManagerObserver();
manetHelper.registerObserver(manetManager);
manetHelper.connectToService();

If I immediately call:

manetHelper.sendStartAdhocCommand();

I'll see the service connected log entry after the onCreate() exists its scope, and the start command never occurs. I thought this might be related to single threading or block because of registering ManetObserver. So, I moved my sendStartAdhocCommand() into an AsyncTask, but there is still some blocking that's going on: (note that executeCommand() constructs the AsyncTask that simply calls the appropriate send command on helper)

manetHelper = new ManetHelper(this);
manetManager = new ManetManagerObserver();
manetHelper.registerObserver(manetManager);
manetHelper.connectToService();
manetManager.executeCommand(manetHelper, OP.START);

I then moved the sendStartAdhocCommand() to a separate Service method that is triggered when an app UI button is touched. When the button is touched, the Service is connected to the Manet Manager service already from onCreate().

My Service has a startService() method that fires up a bunch of Runnables for various tasks. (network communication) It's linked to a button in the app UI. Naturally I need the manet working with an IP address before I can do things like listen on a socket. I added the sendStartAdhocCommand() to my startService() method. The issue here is I need the manet to actually enable, and assign my device an IP in order for me to continue. e.g. I need to wait/block for the manet service to establish.

if(manetHelper.isConnectedToService()) {
manetHelper.sendStartAdhocCommand();
}

I also tried the AsyncTask:

if(manetHelper.isConnectedToService()) {
manetManager.executeCommand(manetHelper, OP.START);
}

And I also tried throwing in a sleep after the start command in both cases.

It doesn't matter what I do. I can't call connectoToService() and sendStartAdhocCommand(), even if I'm doing so from separate threads.

Do you have any suggestions? Thanks!

[jrobble]

@duhmojo - Refer to @daviddoria's ManetStarter code: https://gist.github.com/daviddoria/e34c6ee2c4b5447a8800

Specifically, it's important to wait to call sendStartAdhocCommand() until after the onServiceConnected() callback has been invoked.

If you invoke manetHelper.connectToService() and immediately sleep() or tie up the caller thread then Android will not have an opportunity to pass messages between the Manet Service and your app. Thus you run into a thread blocking problem.

In my experience, you must invoke manetHelper.connectToService() and let the caller thread exit gracefully. In more general terms, you must relinquish control to the Android lifecycle process. This forces you to communicate between your app and the Manet Service in an asynchronous fashion, which is why we use callbacks.

[duhmojo]

Thanks jrobble. I figured it was OS single thread blocking that was happening, but I wanted to get your opinion. The issue is that connecting and starting both have to be in separate threads, before doing anything requiring the manet, in another thread. I think I was close. I'll move the connect and start into the asynctask I was playing with similar to daviddoria's ManaetStarter. Thanks for the feedback.

[daviddoria]

Jeff,

I had a chance to look into a better pattern for doing this. I used
CountDownLatch to block and wait for callbacks. It is much much more
readable now:

https://gist.github.com/daviddoria/3eb8db4632d63d036086

The main logic flow is in in doPrepareNetwork. The file is only so long
because of the many methods that are required to be implemented to derive
from ManetObserver. It is actually quite a simple implementation. Let me
know what you think.

David

On Thu, Oct 17, 2013 at 12:03 PM, duhmojo [email protected] wrote:

Thanks jrobble. I figured it was OS single thread blocking that was
happening, but I wanted to get your opinion. The issue is that connecting
and starting both have to be in separate threads, before doing anything
requiring the manet, in another thread. I think I was close. I'll move the
connect and start into the asynctask I was playing with similar to
daviddoria's ManaetStarter. Thanks for the feedback.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/10#issuecomment-26521414
.

[duhmojo]

Hi David. Did you also make a change to ManetHelper to implement a singleton? ManetHelper.createInstance() doesn't exist in the current code base from what I can tell. I don't think it should matter if I switch to the constructor though since your ManetStart is a singleton itself and it holder the ManetHelper.

[daviddoria]

Yes, I did make that change in my local code base. The point of that gist
is just to demonstrate the flow of "wait for the callback before doing the
next step". It is not designed to be merged as-is (but I think it is a very
useful function to eventually get into master).

David

On Tue, Oct 22, 2013 at 11:34 AM, duhmojo [email protected] wrote:

Hi David. Did you also make a change to ManetHelper to implement a
singleton? ManetHelper.createInstance() doesn't exist in the current code
base from what I can tell. I don't think it should matter if I switch to
the constructor though since your ManetStart is a singleton itself and it
holder the ManetHelper.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/10#issuecomment-26813882
.

[duhmojo]

I gave ManetStarter a try and added support for stopping the network as well. (basically a mirror of DoPrepareNetwork but with a boolean and check set for when the service is connected) It appears to work well but I did this from a regular Activity, not from a Service as I'll have to do eventually. e.g. your app delegates all network communications to a Service, and it needs to make sure that ManetManager is operating normally. I don't think it'll be a big deal. Thanks for sharing your example code.

[jrobble]

@daviddoria - Very good use of Futures. Very clean. Out of curiosity, do you need a separate ExecutorService for the serviceFutureTask and adhocFutureTask, or could you use the same one?

It might be worth creating adapter interfaces that extend ManetObserver and implement all of the necessary callback methods but the one you care about. For example, the AdhocStateObserver can have a default empty implementation for all of the callback methods but onAdhocStateUpdated(). Using such adapter interfaces would make your ManetStarter code less verbose.

[daviddoria]

@daviddoria https://github.com/daviddoria - Very good use of Futures.
Very clean.

Thanks! Yea, it's a heck of a lot easier to follow than the original
method.

Out of curiosity, do you need a separate ExecutorService for the
serviceFutureTask and adhocFutureTask, or could you use the same one?

I have never used these before, but I just tried it with one and just gave
it two threads (newFixedThreadPool(2);) and it seems to work fine.

It might be worth creating adapter interfaces that extend ManetObserver
and implement all of the necessary callback methods but the one you care
about. For example, the AdhocStateObserver can have a default empty
implementation for all of the callback methods but onAdhocStateUpdated().
Using such adapter interfaces would make your ManetStarter code less
verbose.

I created a

// onServiceConnected and onServiceDisconnected are required to be
// implemented by subclasses
abstract public class ManetServiceConnectionObserver implements
ManetObserver
(this simply has empty implementations of all but the two specified
functions, which it simply does not mention at all).

and a

// onAdhocStateUpdated is required to be implemented by subclasses
abstract class AdhocStateObserver implements ManetObserver
(this simply has empty implementations of all but the specified function,
which it simply does not mention at all).

and changed the Callables to

public class StartAdhocCallable extends AdhocStateObserver implements
Callable
and
public class ConnectToServiceCallable extends
ManetServiceConnectionObserver implements Callable

Is that what you were talking about? These are not "interface adapters" I
don't think technically since they are abstract classes and not actual
interfaces, but it seems to get the job done.

[jrobble]

I would think that you could use an ExecutorService with one thread because the serviceFutureTask and adhocFutureTask are not executed at the same time.

Yep, ManetServiceConnectionObserver and AdhocStateObserver are exactly what I'm talking about. You're right, technically what I was referring to as "adapter interfaces" are "adapter abstract classes".

[duhmojo]

You can find the starter I've been trying to get working here (I like the idea of extending a single implementation of the ManetObserver interface, then overriding specific needs from it) it will look similar to David's ManetStarter.

https://github.com/duhmojo/clips/tree/master/ManetService

The main usage class is ManetManagerHelper. It doesn't track the current Manet Manager state, but it will eventually. e.g. so you can query the current manet state as long as you've connected. The idea is to instantiate it, then call the high level commands like so:

ManetManagerHelper helper = manetManagerHelper.getInstance(context);
manetManagerHelper.Connect();
manetManagerHelper.Start();

However I've been running into a nasty concurrency exception that I can't seem to shake. This is probably for Stackoverflow, but it's very hard to re-format my example, or make it generic enough for anyone else to suggest something.

Basically I have a Handler/Runnable in my Activity that runs a managed loop that changes the wifi state, registers wifi scanning, and Manet Manager states. In the UI, pushing a "Start" button will kick off a Runnable that manages all of this:

@Override
public void run() {
    running = true;
    manetManagerHelper.Connect();
    manetManagerHelper.Stop();
    disableWifi();
    while(run) {
        if(!run) return;
        // Start wifi scan for the scan interval specified
        enableWifi();
        for(long stop=System.nanoTime()+TimeUnit.SECONDS.toNanos(1);stop>System.nanoTime();) {
            try {
                Thread.sleep(1000);
                if(stage == STAGES.COMPLETED_SCAN) {
                    // Scan is complete, moving on...
                    disableWifi();
                    enableManet();
                    sendScans();
                    disableManet();
                }
            } catch(Exception e) {
                e.printStackTrace();
            }
        }
}

The first manetManagerHelper.Connect() call will fail with a "Can't create handler inside thread that has not called Looper.prepare()" that occurs in ManetManagerHelper.java line 36, serviceFutureTask.get();

I've removed any trace of UI thread access. You won't see the progress dialog, etc... Right now I'm trying to get this working in a test app with a button controlling the process, but its destined for a Service that will perform this behind the scenes. (its a prototype, there will be rough spots I'm sure)

Any ideas? Most of the clues I've dug up are all related to accessing the main UI thread from a spawned thread. I'm fairly certain I'm not doing anything UI specific in these threads. e.g. like David's progress dialog, etc...

10-24 16:00:18.476: W/System.err(2287): java.util.concurrent.ExecutionException: java.lang.RuntimeException: Can't create handler inside thread that has not called Looper.prepare()
10-24 16:00:18.476: W/System.err(2287): at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:224)
10-24 16:00:18.476: W/System.err(2287): at java.util.concurrent.FutureTask.get(FutureTask.java:83)
10-24 16:00:18.476: W/System.err(2287): at com.test.MainActivity.Connect(MainActivity.java:189)
10-24 16:00:18.476: W/System.err(2287): at com.test.MainActivity.reset(MainActivity.java:172)
10-24 16:00:18.484: W/System.err(2287): at com.test.MainActivity.run(MainActivity.java:124)

[jrobble]

Thanks for sharing @duhmojo. Sorry for the late response.

Have you had any luck solving your concurrency problem?

I usually get “Can't create handler inside thread that has not called Looper.prepare()" because I try to do something UI related on the wrong thread, as you mentioned.

The stack trace you provide seems to before you started using ManetManagerHelper because you’re invoking Connect() on the MainActivity.

[duhmojo]

Ya you're going to think I'm an idiot, but it took this SO post to spell it out for me:

http://stackoverflow.com/questions/14808640/does-a-runnable-in-a-service-run-on-the-ui-thread

I didn't clue in that Runnable is linked to the current Thread. It caused a couple of issues, not the least being that ManetManager would appear to not stop/start until after my thread exited.

Once I switched to a new Thread approach to invoking ManetManagerHelper, things started working better. I now realize David's ManaetStart calls new Thread for a reason in his helper PrepareNetwork method.

I also now have ManetManagerHelper accepting an OnComplete interface used as way to execute callback code when Start and Stop completes. e.g. I want to run code when ManetManager finishes stopping, so I pass in an OnComplete class with onStop() implemented with my code, etc...

This way I've been able to chain a procedure together that stops Manet Manager, performs my Wifi related scanning, then turns the Manet back on.

[duhmojo]

Dumb question, I know I'm starting to hi-jack this thread, but can you explain why ManetHelper.connectToService() needs to be called on the main/UI thread? Is ManetHelper is already connected, then calling ManetHelper.sendStartAdhocCommand() doesn't have to be. I didn't dig in, I'm just trying to see if I can make this work from a Service. Right now it looks as if I'll have to try and pass a reference to the Activity to do so. Its not what I'd like to do, but for right now I just want a working prototype. Thanks.

[jrobble]

I’m not sure if ManetHelper.connectToService() necessarily needs to be called on the main / UI thread. Looking at the implementation of connectToService(), I see that it uses a Context that’s passed in as part of the ManetHelper’s constructor. Then startService() and bindService() are called on that Context. I’m not sure of the Android framework forces those calls to be made on the main / UI thread. You’ll have to try it out.

In general, the ManetHelper is “connected” when the ManetService is started and the Messenger between the ManetHelper and ManetService is created. This is different from starting ad-hoc mode. If you used the ManetHelper to start ad-hoc mode, then the ManetHelper must already be “connected” to the ManetService (unless your app crashed after starting ad-hoc mode). The ManetHelper passes the ManetService commands.

I would think that you should be able to invoke ManetHelper.connectToService() from your service. Just make sure that when you create the ManetHelper that you pass it a reference to your Service class. The ManetHelper constructor takes a Context and both Activity and Service are subclasses of Context.

[duhmojo]

Thanks for the helpful response.

I'm seeing all kinds of issues, regardless of the approach I take. I've currently stripped things down to the bare minimum, but its hard because of what I'm trying to accomplish. Here's a sample of my Service and Observer: (note that the ScannedWifiNodeHelper and ScannedWifiNode simply hold wifi scan data, so nothing special there)

https://github.com/duhmojo/clips/blob/master/ManetService/ExampleManetService.java
https://github.com/duhmojo/clips/blob/master/ManetService/ExampleManetObserver.java

Now the implemented approach has worked, maybe 2 out of 8 times I've tried it, without any major modification. Meaning what I've captured in the logs below illustrate an unreliable method of doing all this, or some instability in the Android/WPA/ManetManager integration. (I know it's complicated, I only want to point out a potential problem)

Service.onCreate() is doing the connect to ManetManager service because I've had trouble with trying to connect, then start/stop the manet from the same thread, and from AsyncTask or new Thread.run. Next I have a method to kick-off the automation of the following:

1. Stopping the manet (it's assumed that the manet is up and running already, this will be worked out later by an initialization process)
2. Enabling Wifi (again, it's assumed that wifi is disabled already, since Manet Manager needs it off to enable the manet)
3. Register a BroadcastReceiver for collecting wifi scan information.
4. When the wifi scans are collected, the BroadcastReceiver needs to be unregistered.
5. Disabled Wifi.
6. Start the manet.

Right now in the sample app, the UI just as a button. The button calls ExampleService.automate().

Here's what I'm seeing after a clean boot. MM isn't running and wifi is already disabled. I start my app, and the Service.onCreate() connects to MM. The MM service fires up and I can see the MM icon in the system bar. (sorry about the length, this is everything I clipped I thought would be useful, it's 90% Manet Manager logs)

03-01 00:15:26.007: I/System.out(1602): debugger has settled (1332)
03-01 00:15:26.328: I/ExampleManetService(1602): Connecting to Manet Manager's Service
03-01 00:15:26.343: I/ActivityManager(1106): Start proc org.span.service.core.ManetService for service org.span/.service.core.ManetService: pid=1613 uid=10054 gids={3003, 3002, 3001, 1015}
03-01 00:15:26.562: I/ActivityManager(1106): Displayed com.drdc.tec3.tec3wifiscanner/.MainActivity: +2s913ms
03-01 00:15:27.117: D/ManetManagerApp(1613): onCreate()
03-01 00:15:27.140: D/ManetService(1613): onCreate()
03-01 00:15:27.148: D/ManetServiceHelper(1613): setup
03-01 00:15:27.148: D/ManetServiceHelper(1613): Current directory is /data/data/org.span
03-01 00:15:27.156: D/ManetServiceHelper(1613): Directory '/data/data/org.span/bin' already exists!
03-01 00:15:27.156: D/ManetServiceHelper(1613): Directory '/data/data/org.span/var' already exists!
03-01 00:15:27.156: D/ManetServiceHelper(1613): Directory '/data/data/org.span/conf' already exists!
03-01 00:15:27.171: D/CoreTask(1613): Writing 624 bytes to file: /mnt/sdcard/manet.conf
03-01 00:15:27.179: D/CoreTask(1613): Writing 624 bytes to file: /data/data/org.span/conf/manet.conf
03-01 00:15:27.179: D/CoreTask(1613): Writing 0 bytes to file: /data/data/org.span/conf/dnsmasq.conf
03-01 00:15:27.179: D/CoreTask(1613): Writing 0 bytes to file: /data/data/org.span/bin/blue-up.sh
03-01 00:15:27.187: D/CoreTask(1613): Writing 0 bytes to file: /data/data/org.span/conf/routing_ignore_list.conf
03-01 00:15:27.187: D/ManetServiceHelper(1613): Creation of configuration files took ==> 8 milliseconds.
03-01 00:15:27.687: D/CoreTask(1613): Writing 624 bytes to file: /mnt/sdcard/manet.conf
03-01 00:15:27.695: D/CoreTask(1613): Writing 624 bytes to file: /data/data/org.span/conf/manet.conf
03-01 00:15:27.695: D/CoreTask(1613): Writing 0 bytes to file: /data/data/org.span/conf/dnsmasq.conf
03-01 00:15:27.695: D/CoreTask(1613): Writing 0 bytes to file: /data/data/org.span/bin/blue-up.sh
03-01 00:15:27.695: D/CoreTask(1613): Writing 0 bytes to file: /data/data/org.span/conf/routing_ignore_list.conf
03-01 00:15:27.695: D/ManetServiceHelper(1613): Creation of configuration files took ==> 6 milliseconds.
03-01 00:15:27.976: D/CoreTask(1613): Root command ==> /data/data/org.span/bin/iwconfig eth0
03-01 00:15:28.015: E/su(1650): sudb - Opening database
03-01 00:15:28.015: E/su(1650): sudb - Database opened
03-01 00:15:28.015: E/su(1650): sudb - Database closed
03-01 00:15:28.039: D/su(1650): 10054 org.span.service.core.ManetService executing 0 "/data/data/org.span/tmp/command.sh" using shell /system/bin/sh : sh
03-01 00:15:28.078: D/CoreTask(1613): eth0      IEEE 802.11-DS  ESSID:""  Nickname:""
03-01 00:15:28.078: D/CoreTask(1613):           Mode:Managed  Frequency:2.412 GHz  Access Point: Not-Associated   
03-01 00:15:28.078: D/CoreTask(1613):           Bit Rate:72 Mb/s   Tx-Power:32 dBm   
03-01 00:15:28.078: D/CoreTask(1613):           Retry min limit:7   RTS thr:off   Fragment thr:off
03-01 00:15:28.078: D/CoreTask(1613):           Encryption key:off
03-01 00:15:28.078: D/CoreTask(1613):           Power Managementmode:All packets received
03-01 00:15:28.078: D/CoreTask(1613):           Link Quality=5/5  Signal level=0 dBm  Noise level=-92 dBm
03-01 00:15:28.078: D/CoreTask(1613):           Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
03-01 00:15:28.078: D/CoreTask(1613):           Tx excessive retries:0  Invalid misc:0   Missed beacon:0
03-01 00:15:28.132: I/ExampleManetObserver(1602): Adhoc State Update: STOPPED
03-01 00:15:28.148: D/ManetService(1613): onStartCommand
03-01 00:15:28.250: D/ManetManagerApp(1613): device: generic
03-01 00:15:28.250: D/ManetManagerApp(1613): onAdhocStateUpdated()
03-01 00:15:34.984: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=2 BSSID=00:00:00:00:00:00]
03-01 00:15:34.984: V/WifiStateTracker(1106): Changing supplicant state: INACTIVE ==> SCANNING
03-01 00:15:34.984: I/test(1437): supplicant AAAAAAAAAAAaa
03-01 00:15:35.554: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:15:35.554: V/WifiStateTracker(1106): Changing supplicant state: SCANNING ==> INACTIVE
03-01 00:15:35.554: I/test(1437): supplicant AAAAAAAAAAAaa
...

Next I click the app's Automate! button. Note the ExampleManetService and ExampleManetObserver are logs from my samples. Also note the wpa_supplicant gets into a funk state where its unable to initiate the scan. But don't draw any conclusions yet! Take a look at the next log clip first.

03-01 00:22:19.171: I/ExampleManetService(1602): 1) Stopping Manet
03-01 00:22:19.210: I/ExampleManetObserver(1602): StopAdhocCallable.call()...
03-01 00:22:19.210: D/ManetServiceHelper(1613): Trying to release locks now
03-01 00:22:19.210: D/ManetServiceHelper(1613): Error while trying to release lock: null
03-01 00:22:19.226: I/ExampleManetService(1602): Adhoc stopped successfully.
03-01 00:22:19.226: I/ExampleManetService(1602): 2) Enabling Wifi
03-01 00:22:19.242: D/ExampleManetService(1602): Enabling wifi...
03-01 00:22:19.250: I/ExampleManetService(1602): Wifi enabled successfully.
03-01 00:22:19.546: D/CoreTask(1613): Root command ==> /data/data/org.span/bin/adhoc stop 1
03-01 00:22:19.585: E/su(1715): sudb - Opening database
03-01 00:22:19.585: E/su(1715): sudb - Database opened
03-01 00:22:19.585: E/su(1715): sudb - Database closed
03-01 00:22:19.601: D/su(1715): 10054 org.span.service.core.ManetService executing 0 "/data/data/org.span/tmp/command.sh" using shell /system/bin/sh : sh
03-01 00:22:19.718: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=0 BSSID=00:00:00:00:00:00]
03-01 00:22:19.726: E/Tethering(1106): attempting to remove unknown iface (eth0), ignoring
03-01 00:22:19.726: V/WifiStateTracker(1106): Changing supplicant state: INACTIVE ==> DISCONNECTED
03-01 00:22:19.726: I/test(1437): supplicant AAAAAAAAAAAaa
03-01 00:22:19.726: D/NetdConnector(1106): RCV <- {600 Iface removed eth0}
03-01 00:22:19.765: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:22:19.765: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd, counter: 1, Maxmum: 30)
03-01 00:22:19.765: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:22:19.765: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd, counter: 2, Maxmum: 30)
03-01 00:22:21.249: D/ExampleManetService(1602): Test: Wifi is: enabled
03-01 00:22:21.249: I/ExampleManetService(1602): 3) Register Wifi Receiver to collect scans
03-01 00:22:21.257: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=2 BSSID=00:00:00:00:00:00]
03-01 00:22:21.257: V/WifiStateTracker(1106): Changing supplicant state: DISCONNECTED ==> SCANNING
03-01 00:22:21.257: I/test(1437): supplicant AAAAAAAAAAAaa
03-01 00:22:21.265: E/wpa_supplicant(1263): ioctl[SIOCSIWPRIV] (cscan): -1
03-01 00:22:21.265: W/wpa_supplicant(1263): Failed to initiate AP scan.
03-01 00:22:21.265: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:22:21.265: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd, counter: 3, Maxmum: 30)
03-01 00:22:21.265: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:22:21.265: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd, counter: 4, Maxmum: 30)
03-01 00:22:22.375: D/ManetManagerApp(1613): onAdhocStateUpdated()
03-01 00:22:22.406: I/ExampleManetObserver(1602): Adhoc State Update: STOPPED
03-01 00:22:24.726: D/WifiStateTracker(1106): Reset connections and stopping DHCP
03-01 00:22:25.734: D/WifiStateTracker(1106): Disabling interface
03-01 00:22:25.742: I/test(1437): netwrokd state BBBBBBBBBBBBBBBBBBBB
03-01 00:22:25.742: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:22:25.742: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd, counter: 5, Maxmum: 30)
03-01 00:22:25.742: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:22:25.742: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd, counter: 6, Maxmum: 30)
03-01 00:22:30.765: D/dalvikvm(1452): GC_EXPLICIT freed 228K, 49% free 2817K/5511K, external 1690K/2137K, paused 28ms
03-01 00:22:31.265: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:22:31.265: V/WifiStateTracker(1106): Changing supplicant state: SCANNING ==> INACTIVE
03-01 00:22:31.273: I/test(1437): supplicant AAAAAAAAAAAaa
03-01 00:22:31.273: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:22:31.273: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd, counter: 7, Maxmum: 30)
03-01 00:22:31.273: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:22:31.273: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd, counter: 8, Maxmum: 30)

Ok, this last clip is really large, I know, but it's all related to WPA and Manet Manager. Note the time my app registered the BroadcastReceiver:
03-01 00:22:21.249: I/ExampleManetService(1602): 3) Register Wifi Receiver to collect scans

Then when it received its first callback:
03-01 00:25:06.695: D/ExampleManetService(1602): Calling Receiver onReceive count: 1

There's 2.5 minute gap with a fair bit of error logs firing in between.

03-01 00:25:01.453: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:25:01.453: V/WifiStateTracker(1106): Changing supplicant state: SCANNING ==> INACTIVE
03-01 00:25:01.453: I/test(1437): supplicant AAAAAAAAAAAaa
03-01 00:25:01.468: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:25:01.468: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd, counter: 31, Maxmum: 30)
03-01 00:25:01.468: E/wpa_supplicant(1263): send priv command error over maxmum 30 times
03-01 00:25:01.468: V/WifiMonitor(1106): Event [CTRL-EVENT-DRIVER-STATE HANGED]
03-01 00:25:01.468: E/WifiStateTracker(1106): Wifi Driver reports HUNG - reloading.
03-01 00:25:01.500: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:25:01.500: E/wpa_supplicant(1263): wpa_driver_priv_driver_cmd, counter: 1, Maxmum: 30)
03-01 00:25:01.500: D/WifiHW(1106): Enter stop supplicant
03-01 00:25:01.500: I/WifiHW(1106):   ++ctl.stop <wpa_supplicant>
03-01 00:25:01.500: I/WifiHW(1106):   --ctl.stop <wpa_supplicant>
03-01 00:25:01.500: V/WifiMonitor(1106): Event [CTRL-EVENT-TERMINATING - signal 15 received]
03-01 00:25:01.500: E/wpa_supplicant(1263): Failed to disable WPA in the driver.
03-01 00:25:02.515: E/wpa_supplicant(1263): ioctl[SIOCGIWMODE]
03-01 00:25:02.531: E/wpa_supplicant(1263): ioctl[SIOCSIWAP]
03-01 00:25:02.531: E/wpa_supplicant(1263): ioctl[SIOCGIFFLAGS]
03-01 00:25:02.617: D/WifiHW(1106): Supplicant have stopped successfully, count: 38
03-01 00:25:02.617: D/WifiStateTracker(1106): Reset connections and stopping DHCP
03-01 00:25:02.617: V/WifiStateTracker(1106): Connection to supplicant lost
03-01 00:25:02.617: D/WifiHW(1106): Starting close supplicant.......
03-01 00:25:03.624: D/WifiStateTracker(1106): Disabling interface
03-01 00:25:03.624: D/WifiHW(1106): >>> wifi_unload_driver
03-01 00:25:03.624: D/WifiHW(1106): >>> rmmod
03-01 00:25:03.624: D/WifiHW(1106): Unable to unload driver module "dhd": No such file or directory
03-01 00:25:03.624: I/WifiHW(1106): >>> set_wifi_power: 0
03-01 00:25:03.624: I/WifiHW(1106): <<< set_wifi_power
03-01 00:25:03.726: D/WifiHW(1106): <<< rmmod= -1
03-01 00:25:03.726: D/WifiHW(1106): >>> wifi_load_driver
03-01 00:25:03.726: E/WifiService(1106): Failed to unload Wi-Fi driver.
03-01 00:25:03.742: D/WifiHW(1106): >>> check_driver_loaded
03-01 00:25:03.742: D/WifiHW(1106): Driver is loaded, get wlan.driver.status status: ok
03-01 00:25:03.742: D/WifiHW(1106):   open "/proc/modules"
03-01 00:25:03.742: D/WifiHW(1106): get wlan.driver.status status: unloaded
03-01 00:25:03.742: D/WifiHW(1106): <<< check_driver_loaded
03-01 00:25:03.742: D/WifiHW(1106): >>> insmod, filename= "/system/proprietary/wifi/dhd.ko", args= "firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt"
03-01 00:25:03.742: I/WifiHW(1106): >>> set_wifi_power: 1
03-01 00:25:03.765: I/WifiHW(1106): <<< set_wifi_power
03-01 00:25:04.476: D/Tethering(1106): interfaceAdded: eth0
03-01 00:25:04.476: D/Tethering(1106): isWifi()  regex: wl0.1, iface: eth0
03-01 00:25:04.476: D/Tethering(1106): isUsb()  regex: usb0, iface: eth0
03-01 00:25:04.476: D/Tethering(1106): eth0 is not a tetherable iface, ignoring
03-01 00:25:04.476: D/NetdConnector(1106): RCV <- {600 Iface added eth0}
03-01 00:25:04.492: D/WifiHW(1106): <<< insmod, ret= 0
03-01 00:25:05.492: D/WifiHW(1106): #### wifi_load_driver, load firmware O.K ####
03-01 00:25:05.492: D/WifiHW(1106): get wlan.driver.status status: ok
03-01 00:25:05.492: D/WifiHW(1106): <<< wifi_load_driver,ok
03-01 00:25:05.492: D/WifiHW(1106): Starting supplicant.......
03-01 00:25:05.492: D/WifiHW(1106): <<< ensure_config_file_exists, access
03-01 00:25:05.492: I/WifiHW(1106):   ++ctl.start <wpa_supplicant>
03-01 00:25:05.492: I/WifiHW(1106):   --ctl.start <wpa_supplicant>
03-01 00:25:05.492: D/WifiHW(1106): Starting supplicant successfully, count: 199
03-01 00:25:05.507: E/WifiHW(1106): Not connected to wpa_supplicant - "BLACKLIST clear" command dropped.
03-01 00:25:05.515: D/WifiHW(1106): Starting connect to supplicant...
03-01 00:25:05.515: D/WifiHW(1106): WIFI_TEST_INTERFACE: "eth0", iface: "eth0"
03-01 00:25:05.515: D/WifiHW(1106): IFACE_DIR: "/data/misc/wifi/sockets", iface: "eth0"
03-01 00:25:05.515: D/WifiHW(1106):   ifname = eth0
03-01 00:25:05.617: D/WifiHW(1106): Retry to wpa_ctrl_open 
03-01 00:25:05.617: D/WifiHW(1106): Connect to supplicant successfully
03-01 00:25:05.617: D/WifiStateTracker(1106): Reset connections and stopping DHCP
03-01 00:25:05.656: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=2 BSSID=00:00:00:00:00:00]
03-01 00:25:06.632: D/WifiStateTracker(1106): Disabling interface
03-01 00:25:06.640: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:25:06.656: V/WifiStateTracker(1106): Connection to supplicant established, state=INACTIVE
03-01 00:25:06.671: V/WifiStateTracker(1106): Changing supplicant state: INACTIVE ==> SCANNING
03-01 00:25:06.671: V/WifiStateTracker(1106): Changing supplicant state: SCANNING ==> INACTIVE
03-01 00:25:06.695: D/ExampleManetService(1602): onReceived: android.net.wifi.SCAN_RESULTS
03-01 00:25:06.695: I/test(1437): supplicant AAAAAAAAAAAaa
03-01 00:25:06.695: D/ExampleManetService(1602): Calling Receiver onReceive count: 1
03-01 00:25:06.703: D/ExampleManetService(1602): Receiver scan interval limit reached...
03-01 00:25:06.703: I/ExampleManetService(1602): 4) Unregistering receiver
03-01 00:25:06.710: I/ExampleManetService(1602): 5) Disable Wifi...
03-01 00:25:06.718: D/ExampleManetService(1602): Enabling wifi...
03-01 00:25:06.718: I/ExampleManetService(1602): Wifi disabled successfully.
03-01 00:25:06.718: I/ExampleManetService(1602): 6) Start Manet Manager...
03-01 00:25:06.734: I/ExampleManetObserver(1602): StartAdhocCallable.call()...
03-01 00:25:06.734: D/WifiHW(1106): Enter stop supplicant
03-01 00:25:06.734: I/WifiHW(1106):   ++ctl.stop <wpa_supplicant>
03-01 00:25:06.734: I/WifiHW(1106):   --ctl.stop <wpa_supplicant>
03-01 00:25:06.742: V/WifiMonitor(1106): Event [CTRL-EVENT-TERMINATING - signal 15 received]
03-01 00:25:06.750: D/ManetServiceHelper(1613): Wifi disabled!
03-01 00:25:06.765: I/ExampleManetService(1602): Adhoc started successfully.
03-01 00:25:06.765: D/ExampleManetService(1602): onReceived: android.net.wifi.SCAN_RESULTS
03-01 00:25:06.781: I/test(1437): supplicant AAAAAAAAAAAaa
03-01 00:25:07.781: D/WifiHW(1106): Supplicant have stopped successfully, count: 39
03-01 00:25:07.781: D/WifiStateTracker(1106): Reset connections and stopping DHCP
03-01 00:25:07.789: V/WifiStateTracker(1106): Connection to supplicant lost
03-01 00:25:07.789: D/WifiHW(1106): Starting close supplicant.......
03-01 00:25:08.789: D/WifiStateTracker(1106): Disabling interface
03-01 00:25:08.789: D/WifiHW(1106): >>> wifi_unload_driver
03-01 00:25:08.789: D/WifiHW(1106): >>> rmmod
03-01 00:25:08.796: E/Tethering(1106): attempting to remove unknown iface (eth0), ignoring
03-01 00:25:08.796: D/NetdConnector(1106): RCV <- {600 Iface removed eth0}
03-01 00:25:09.070: I/WifiHW(1106): >>> set_wifi_power: 0
03-01 00:25:09.070: I/WifiHW(1106): <<< set_wifi_power
03-01 00:25:09.171: D/WifiHW(1106): <<< rmmod= 0
03-01 00:25:09.171: D/WifiHW(1106): >>> check_driver_loaded
03-01 00:25:09.171: D/WifiHW(1106): Driver is loaded, get wlan.driver.status status: ok
03-01 00:25:09.171: D/WifiHW(1106):   open "/proc/modules"
03-01 00:25:09.171: D/WifiHW(1106): get wlan.driver.status status: unloaded
03-01 00:25:09.171: D/WifiHW(1106): <<< check_driver_loaded
03-01 00:25:09.171: D/WifiHW(1106): unload wifi driver successfully, count = 19 (20->0)
03-01 00:25:10.109: I/test(1437): I will sleep ten minutes
03-01 00:25:11.757: D/CoreTask(1613): Root command ==> /data/data/org.span/bin/adhoc start 1
03-01 00:25:11.843: E/su(1899): sudb - Opening database
03-01 00:25:11.859: E/su(1899): sudb - Database opened
03-01 00:25:11.859: E/su(1899): sudb - Database closed
03-01 00:25:11.859: D/su(1899): 10054 org.span.service.core.ManetService executing 0 "/data/data/org.span/tmp/command.sh" using shell /system/bin/sh : sh
03-01 00:25:11.984: D/WifiHW(1902): >>> wifi_load_driver
03-01 00:25:11.984: I/WifiHW(1902): >>> init_rfkill
03-01 00:25:11.984: I/WifiHW(1902):   wlan
03-01 00:25:11.984: I/WifiHW(1902): , rfkill_id: 0
03-01 00:25:11.984: I/WifiHW(1902):   rfkill_state_path_wifi: /sys/class/rfkill/rfkill0/state
03-01 00:25:11.984: I/WifiHW(1902): <<< init_rfkill
03-01 00:25:11.984: D/WifiHW(1902): >>> check_driver_loaded
03-01 00:25:11.984: D/WifiHW(1902): Driver is NOT loaded, get wlan.driver.status status: unloaded
03-01 00:25:11.984: D/WifiHW(1902): >>> insmod, filename= "/system/proprietary/wifi/dhd.ko", args= "firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt"
03-01 00:25:11.984: I/WifiHW(1902): >>> set_wifi_power: 1
03-01 00:25:11.984: I/WifiHW(1902): <<< set_wifi_power
03-01 00:25:12.781: D/Tethering(1106): interfaceAdded: eth0
03-01 00:25:12.781: D/Tethering(1106): isWifi()  regex: wl0.1, iface: eth0
03-01 00:25:12.781: D/Tethering(1106): isUsb()  regex: usb0, iface: eth0
03-01 00:25:12.781: D/Tethering(1106): eth0 is not a tetherable iface, ignoring
03-01 00:25:12.781: D/NetdConnector(1106): RCV <- {600 Iface added eth0}
03-01 00:25:12.789: D/WifiHW(1902): <<< insmod, ret= 0
03-01 00:25:13.789: D/WifiHW(1902): #### wifi_load_driver, load firmware O.K ####
03-01 00:25:13.789: D/WifiHW(1902): get wlan.driver.status status: ok
03-01 00:25:13.789: D/WifiHW(1902): <<< wifi_load_driver,ok
03-01 00:25:15.156: D/dalvikvm(1602): GC_CONCURRENT freed 451K, 58% free 2835K/6663K, external 1625K/2137K, paused 2ms+3ms
03-01 00:25:15.898: D/CoreTask(1613): Root command ==> /data/data/org.span/bin/iwconfig eth0
03-01 00:25:15.976: E/su(1944): sudb - Opening database
03-01 00:25:15.976: D/dalvikvm(1613): GC_CONCURRENT freed 540K, 58% free 2857K/6727K, external 1657K/2137K, paused 3ms+14ms
03-01 00:25:15.984: E/su(1944): sudb - Database opened
03-01 00:25:15.984: E/su(1944): sudb - Database closed
03-01 00:25:15.992: D/su(1944): 10054 org.span.service.core.ManetService executing 0 "/data/data/org.span/tmp/command.sh" using shell /system/bin/sh : sh
03-01 00:25:16.023: D/CoreTask(1613): eth0      IEEE 802.11-DS  ESSID:"AndroidAdhoc"  Nickname:""
03-01 00:25:16.023: D/CoreTask(1613):           Mode:Ad-Hoc  Frequency:2.412 GHz  Cell: 7E:99:D9:96:33:4E   
03-01 00:25:16.023: D/CoreTask(1613):           Bit Rate=72 Mb/s   Tx-Power:32 dBm   
03-01 00:25:16.023: D/CoreTask(1613):           Retry min limit:7   RTS thr:off   Fragment thr:off
03-01 00:25:16.023: D/CoreTask(1613):           Encryption key:off
03-01 00:25:16.023: D/CoreTask(1613):           Power Managementmode:All packets received
03-01 00:25:16.023: D/CoreTask(1613):           Link Quality=5/5  Signal level=-57 dBm  Noise level=-92 dBm
03-01 00:25:16.023: D/CoreTask(1613):           Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
03-01 00:25:16.023: D/CoreTask(1613):           Tx excessive retries:0  Invalid misc:0   Missed beacon:0
03-01 00:25:16.367: D/CoreTask(1613): Root command ==> /data/data/org.span/bin/olsrd -f /data/data/org.span/conf/olsrd.conf -d 6 -ignore /data/data/org.span/conf/routing_ignore_list.conf
03-01 00:25:16.414: E/su(1952): sudb - Opening database
03-01 00:25:16.414: E/su(1952): sudb - Database opened
03-01 00:25:16.414: E/su(1952): sudb - Database closed
03-01 00:25:16.421: D/su(1952): 10054 org.span.service.core.ManetService executing 0 "/data/data/org.span/tmp/command.sh" using shell /system/bin/sh : sh
03-01 00:25:16.460: I/olsrd(1957): Writing '1' (was 1) to /proc/sys/net/ipv4/ip_forward
03-01 00:25:16.468: I/olsrd(1957): Writing '0' (was 1) to /proc/sys/net/ipv4/conf/all/send_redirects
03-01 00:25:16.468: I/olsrd(1957): Writing '0' (was 0) to /proc/sys/net/ipv4/conf/all/rp_filter
03-01 00:25:16.468: I/olsrd(1957): Writing '0' (was 1) to /proc/sys/net/ipv4/conf/eth0/send_redirects
03-01 00:25:16.468: I/olsrd(1957): Writing '0' (was 0) to /proc/sys/net/ipv4/conf/eth0/rp_filter
03-01 00:25:16.468: I/olsrd(1957): Adding interface eth0
03-01 00:25:16.468: I/olsrd(1957): New main address: 192.168.1.104
03-01 00:25:16.476: I/olsrd(1957): olsr.org -  pre-0.6.3-git_98cbd3d-hash_ successfully started
03-01 00:25:17.414: D/CoreTask(1613): Root command ==> setprop net.dns1 208.67.222.222
03-01 00:25:17.453: E/su(1960): sudb - Opening database
03-01 00:25:17.453: E/su(1960): sudb - Database opened
03-01 00:25:17.460: E/su(1960): sudb - Database closed
03-01 00:25:17.460: D/su(1960): 10054 org.span.service.core.ManetService executing 0 "/data/data/org.span/tmp/command.sh" using shell /system/bin/sh : sh
03-01 00:25:17.476: D/ManetServiceHelper(1613): Trying to acquire locks now
03-01 00:25:17.476: D/WifiService(1106): mWifiEnabled -> false
03-01 00:25:17.890: E/su(1969): sudb - Opening database
03-01 00:25:17.890: E/su(1969): sudb - Database opened
03-01 00:25:17.890: E/su(1969): sudb - Database closed
03-01 00:25:17.898: D/su(1969): 10054 org.span.service.core.ManetService executing 0 "/data/data/org.span/tmp/command.sh" using shell /system/bin/sh : sh
03-01 00:25:17.914: D/CoreTask(1613): eth0      IEEE 802.11-DS  ESSID:"AndroidAdhoc"  Nickname:""
03-01 00:25:17.914: D/CoreTask(1613):           Mode:Ad-Hoc  Frequency:2.412 GHz  Cell: 7E:99:D9:96:33:4E   
03-01 00:25:17.914: D/CoreTask(1613):           Bit Rate=72 Mb/s   Tx-Power:32 dBm   
03-01 00:25:17.914: D/CoreTask(1613):           Retry min limit:7   RTS thr:off   Fragment thr:off
03-01 00:25:17.914: D/CoreTask(1613):           Encryption key:off
03-01 00:25:17.914: D/CoreTask(1613):           Power Managementmode:All packets received
03-01 00:25:17.914: D/CoreTask(1613):           Link Quality=5/5  Signal level=-57 dBm  Noise level=-92 dBm
03-01 00:25:17.914: D/CoreTask(1613):           Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
03-01 00:25:17.914: D/CoreTask(1613):           Tx excessive retries:0  Invalid misc:0   Missed beacon:0
03-01 00:25:17.945: D/ManetServiceHelper(1613): Alarm activated!
03-01 00:25:17.945: D/ManetServiceHelper(1613): Trying to acquire locks now
03-01 00:25:17.968: D/ManetManagerApp(1613): onAdhocStateUpdated()
03-01 00:25:18.007: I/ExampleManetObserver(1602): Adhoc State Update: STARTED
03-01 00:25:30.000: D/ManetServiceHelper(1613): Alarm activated!
03-01 00:25:30.000: D/ManetServiceHelper(1613): Trying to acquire locks now
03-01 00:26:00.000: D/ManetServiceHelper(1613): Alarm activated!
03-01 00:26:00.000: D/ManetServiceHelper(1613): Trying to acquire locks now
03-01 00:26:30.000: D/ManetServiceHelper(1613): Alarm activated!
03-01 00:26:30.000: D/ManetServiceHelper(1613): Trying to acquire locks now

FINALLY, here's a log from a successful automation of the process. You'll see it takes all of 1.5 seconds to complete, in spite of what looks like possible errors. Also, note the final log line:

03-01 00:48:40.656: D/WifiHW(1091): Supplicant have stopped successfully, count: 39

I definitely didn't stop the manet 39 times since my last clean reboot.

03-01 00:47:12.000: I/WifiExampleManetService(1569): 1) Stopping Manet
03-01 00:47:12.015: I/ExampleManetObserver(1569): StopAdhocCallable.call()...
03-01 00:47:12.015: D/ManetServiceHelper(1590): Trying to release locks now
03-01 00:47:12.031: I/WifiExampleManetService(1569): Adhoc stopped successfully.
03-01 00:47:12.031: I/WifiExampleManetService(1569): 2) Enabling Wifi
03-01 00:47:12.046: D/WifiExampleManetService(1569): Enabling wifi...
03-01 00:47:12.054: D/WifiHW(1091): >>> wifi_load_driver
03-01 00:47:12.054: D/WifiHW(1091): <<< wifi_load_driver loaded already, wifi power is ON
03-01 00:47:12.054: D/WifiHW(1091): Starting supplicant.......
03-01 00:47:12.054: D/WifiHW(1091): <<< ensure_config_file_exists, access
03-01 00:47:12.054: I/WifiHW(1091):   ++ctl.start <wpa_supplicant>
03-01 00:47:12.054: I/WifiHW(1091):   --ctl.start <wpa_supplicant>
03-01 00:47:12.078: I/WifiExampleManetService(1569): Wifi enabled successfully.
03-01 00:47:12.078: D/WifiHW(1091): Starting supplicant successfully, count: 199
03-01 00:47:12.093: D/WifiHW(1091): Starting connect to supplicant...
03-01 00:47:12.093: D/WifiHW(1091): WIFI_TEST_INTERFACE: "eth0", iface: "eth0"
03-01 00:47:12.093: D/WifiHW(1091): IFACE_DIR: "/data/misc/wifi/sockets", iface: "eth0"
03-01 00:47:12.093: D/WifiHW(1091):   ifname = eth0
03-01 00:47:12.109: E/wpa_supplicant(1810): ioctl[SIOCSIWMODE]
03-01 00:47:12.171: D/WifiService(1091): mWifiEnabled -> true
03-01 00:47:12.187: D/WifiHW(1091): Connect to supplicant successfully
03-01 00:47:12.187: D/WifiStateTracker(1091): Reset connections and stopping DHCP
03-01 00:47:12.234: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=2 BSSID=00:00:00:00:00:00]
03-01 00:47:12.414: D/CoreTask(1590): Root command ==> kill -9 1775
03-01 00:47:12.468: E/su(1815): sudb - Opening database
03-01 00:47:12.468: E/su(1815): sudb - Database opened
03-01 00:47:12.476: E/su(1815): sudb - Database closed
03-01 00:47:12.492: D/su(1815): 10054 org.span.service.core.ManetService executing 0 "/data/data/org.span/tmp/command.sh" using shell /system/bin/sh : sh
03-01 00:47:12.523: D/CoreTask(1590): Root command ==> /data/data/org.span/bin/adhoc stop 1
03-01 00:47:12.585: E/su(1821): sudb - Opening database
03-01 00:47:12.593: E/su(1821): sudb - Database opened
03-01 00:47:12.601: E/su(1821): sudb - Database closed
03-01 00:47:12.609: D/su(1821): 10054 org.span.service.core.ManetService executing 0 "/data/data/org.span/tmp/command.sh" using shell /system/bin/sh : sh
03-01 00:47:12.687: E/Tethering(1091): attempting to remove unknown iface (eth0), ignoring
03-01 00:47:12.687: D/NetdConnector(1091): RCV <- {600 Iface removed eth0}
03-01 00:47:13.203: D/WifiStateTracker(1091): Disabling interface
03-01 00:47:13.203: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): START
03-01 00:47:13.203: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 1, Maxmum: 30)
03-01 00:47:13.203: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): MACADDR
03-01 00:47:13.203: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 2, Maxmum: 30)
03-01 00:47:13.203: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=0 BSSID=00:00:00:00:00:00]
03-01 00:47:13.203: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:47:13.203: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 3, Maxmum: 30)
03-01 00:47:13.203: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:47:13.203: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 4, Maxmum: 30)
03-01 00:47:13.203: V/WifiStateTracker(1091): Connection to supplicant established, state=DISCONNECTED
03-01 00:47:13.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RXFILTER-ADD 0
03-01 00:47:13.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 5, Maxmum: 30)
03-01 00:47:13.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): BTCOEXSCAN-STOP
03-01 00:47:13.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 6, Maxmum: 30)
03-01 00:47:13.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): COUNTRY EU
03-01 00:47:13.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 7, Maxmum: 30)
03-01 00:47:13.210: V/WifiStateTracker(1091): Changing supplicant state: DISCONNECTED ==> SCANNING
03-01 00:47:13.210: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:47:13.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): SCAN-PASSIVE
03-01 00:47:13.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 8, Maxmum: 30)
03-01 00:47:13.210: V/WifiStateTracker(1091): Changing supplicant state: SCANNING ==> DISCONNECTED
03-01 00:47:13.218: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:47:13.218: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 9, Maxmum: 30)
03-01 00:47:13.218: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:47:13.218: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 10, Maxmum: 30)
03-01 00:47:13.218: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:47:13.218: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:47:13.218: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 11, Maxmum: 30)
03-01 00:47:13.218: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:47:13.218: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 12, Maxmum: 30)
03-01 00:47:14.078: D/WifiExampleManetService(1569): Test: Wifi is: enabled
03-01 00:47:14.078: I/WifiExampleManetService(1569): 3) Register Wifi Receiver to collect scans
03-01 00:47:14.078: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=2 BSSID=00:00:00:00:00:00]
03-01 00:47:14.085: V/WifiStateTracker(1091): Changing supplicant state: DISCONNECTED ==> SCANNING
03-01 00:47:14.085: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:47:14.085: E/wpa_supplicant(1810): ioctl[SIOCSIWPRIV] (cscan): -1
03-01 00:47:14.085: W/wpa_supplicant(1810): Failed to initiate AP scan.
03-01 00:47:14.085: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:47:14.085: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 13, Maxmum: 30)
03-01 00:47:14.085: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:47:14.085: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 14, Maxmum: 30)
03-01 00:47:18.226: D/WifiStateTracker(1091): Reset connections and stopping DHCP
03-01 00:47:19.117: D/dalvikvm(1288): GC_EXPLICIT freed 135K, 48% free 2810K/5379K, external 1625K/2137K, paused 29ms
03-01 00:47:19.226: I/test(1357): netwrokd state BBBBBBBBBBBBBBBBBBBB
03-01 00:47:19.226: D/WifiStateTracker(1091): Disabling interface
03-01 00:47:19.234: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:47:19.234: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 15, Maxmum: 30)
03-01 00:47:19.234: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:47:19.234: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 16, Maxmum: 30)
03-01 00:47:20.000: D/ManetServiceHelper(1590): Wifi started!
03-01 00:47:20.289: D/ManetManagerApp(1590): onAdhocStateUpdated()
03-01 00:47:20.289: I/ExampleManetObserver(1569): Adhoc State Update: STOPPED
03-01 00:47:24.093: E/wpa_supplicant(1810): ioctl[SIOCGIWSCAN]: 19
03-01 00:47:24.093: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:47:24.093: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:47:24.093: V/WifiStateTracker(1091): Changing supplicant state: SCANNING ==> INACTIVE
03-01 00:47:24.093: V/WifiStateTracker(1091): Changing supplicant state: INACTIVE ==> INACTIVE
03-01 00:47:24.093: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:47:24.093: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:47:24.093: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 17, Maxmum: 30)
03-01 00:47:24.093: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:47:24.093: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 18, Maxmum: 30)
03-01 00:47:29.125: D/dalvikvm(1382): GC_EXPLICIT freed 379K, 50% free 2859K/5703K, external 1690K/2137K, paused 30ms
03-01 00:47:29.992: D/ManetServiceHelper(1590): Alarm activated!
03-01 00:47:39.109: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=2 BSSID=00:00:00:00:00:00]
03-01 00:47:39.109: V/WifiStateTracker(1091): Changing supplicant state: INACTIVE ==> SCANNING
03-01 00:47:39.109: E/wpa_supplicant(1810): ioctl[SIOCSIWPRIV] (cscan): -1
03-01 00:47:39.109: W/wpa_supplicant(1810): Failed to initiate AP scan.
03-01 00:47:39.109: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:47:39.109: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 19, Maxmum: 30)
03-01 00:47:39.109: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:47:39.109: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 20, Maxmum: 30)
03-01 00:47:39.109: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:47:49.125: E/wpa_supplicant(1810): ioctl[SIOCGIWSCAN]: 19
03-01 00:47:49.125: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:47:49.125: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:47:49.125: V/WifiStateTracker(1091): Changing supplicant state: SCANNING ==> INACTIVE
03-01 00:47:49.125: V/WifiStateTracker(1091): Changing supplicant state: INACTIVE ==> INACTIVE
03-01 00:47:49.125: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:47:49.125: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:47:49.125: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 21, Maxmum: 30)
03-01 00:47:49.125: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:47:49.125: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 22, Maxmum: 30)
03-01 00:47:55.429: E/GpsLocationProvider(1091): Error getting cell location info.
03-01 00:47:55.429: I/gps_BRCM(1068): @(#)Broadcom GPS ver. 2.1.3.112831,Oct 26 2011, 00:31:14
03-01 00:48:00.000: D/ManetServiceHelper(1590): Alarm activated!
03-01 00:48:04.140: V/WifiStateTracker(1091): Changing supplicant state: INACTIVE ==> SCANNING
03-01 00:48:04.140: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:48:04.140: E/wpa_supplicant(1810): ioctl[SIOCSIWPRIV] (cscan): -1
03-01 00:48:04.140: W/wpa_supplicant(1810): Failed to initiate AP scan.
03-01 00:48:04.140: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:48:04.140: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 23, Maxmum: 30)
03-01 00:48:04.140: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:48:04.140: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 24, Maxmum: 30)
03-01 00:48:04.140: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=2 BSSID=00:00:00:00:00:00]
03-01 00:48:14.148: E/wpa_supplicant(1810): ioctl[SIOCGIWSCAN]: 19
03-01 00:48:14.148: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:48:14.148: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:48:14.148: V/WifiStateTracker(1091): Changing supplicant state: SCANNING ==> INACTIVE
03-01 00:48:14.156: V/WifiStateTracker(1091): Changing supplicant state: INACTIVE ==> INACTIVE
03-01 00:48:14.156: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:48:14.171: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:48:14.171: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 25, Maxmum: 30)
03-01 00:48:14.171: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:48:14.171: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 26, Maxmum: 30)
03-01 00:48:29.171: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=2 BSSID=00:00:00:00:00:00]
03-01 00:48:29.171: V/WifiStateTracker(1091): Changing supplicant state: INACTIVE ==> SCANNING
03-01 00:48:29.171: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:48:29.171: E/wpa_supplicant(1810): ioctl[SIOCSIWPRIV] (cscan): -1
03-01 00:48:29.171: W/wpa_supplicant(1810): Failed to initiate AP scan.
03-01 00:48:29.171: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:48:29.171: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 27, Maxmum: 30)
03-01 00:48:29.171: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:48:29.171: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 28, Maxmum: 30)
03-01 00:48:29.999: D/ManetServiceHelper(1590): Alarm activated!
03-01 00:48:34.187: V/NFC(1288): this device does not have NFC support
03-01 00:48:34.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:48:34.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 29, Maxmum: 30)
03-01 00:48:34.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:48:34.210: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 30, Maxmum: 30)
03-01 00:48:34.218: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-01 00:48:34.218: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 31, Maxmum: 30)
03-01 00:48:34.218: E/wpa_supplicant(1810): send priv command error over maxmum 30 times
03-01 00:48:34.218: V/WifiMonitor(1091): Event [CTRL-EVENT-DRIVER-STATE HANGED]
03-01 00:48:34.218: E/WifiStateTracker(1091): Wifi Driver reports HUNG - reloading.
03-01 00:48:34.234: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-01 00:48:34.234: E/wpa_supplicant(1810): wpa_driver_priv_driver_cmd, counter: 1, Maxmum: 30)
03-01 00:48:34.234: D/WifiHW(1091): Enter stop supplicant
03-01 00:48:34.234: I/WifiHW(1091):   ++ctl.stop <wpa_supplicant>
03-01 00:48:34.234: I/WifiHW(1091):   --ctl.stop <wpa_supplicant>
03-01 00:48:34.242: V/WifiMonitor(1091): Event [CTRL-EVENT-TERMINATING - signal 15 received]
03-01 00:48:34.257: E/wpa_supplicant(1810): Failed to disable WPA in the driver.
03-01 00:48:34.570: I/ActivityManager(1091): Displayed com.android.settings/.WirelessSettings: +455ms
03-01 00:48:35.273: E/wpa_supplicant(1810): ioctl[SIOCGIWMODE]
03-01 00:48:35.273: E/wpa_supplicant(1810): ioctl[SIOCSIWAP]
03-01 00:48:35.273: E/wpa_supplicant(1810): ioctl[SIOCGIFFLAGS]
03-01 00:48:35.367: D/WifiHW(1091): Supplicant have stopped successfully, count: 38
03-01 00:48:35.367: D/WifiStateTracker(1091): Reset connections and stopping DHCP
03-01 00:48:35.367: V/WifiStateTracker(1091): Connection to supplicant lost
03-01 00:48:35.367: D/WifiHW(1091): Starting close supplicant.......
03-01 00:48:35.445: I/gps_BRCM(1068): @(#)Broadcom GPS ver. 2.1.3.112831,Oct 26 2011, 00:31:14
03-01 00:48:35.445: E/GpsLocationProvider(1091): Error getting cell location info.
03-01 00:48:36.367: D/WifiHW(1091): >>> wifi_unload_driver
03-01 00:48:36.367: D/WifiHW(1091): >>> rmmod
03-01 00:48:36.367: D/WifiHW(1091): Unable to unload driver module "dhd": No such file or directory
03-01 00:48:36.367: I/WifiHW(1091): >>> set_wifi_power: 0
03-01 00:48:36.367: I/WifiHW(1091): <<< set_wifi_power
03-01 00:48:36.367: D/WifiStateTracker(1091): Disabling interface
03-01 00:48:36.468: D/WifiHW(1091): <<< rmmod= -1
03-01 00:48:36.468: D/WifiHW(1091): >>> wifi_load_driver
03-01 00:48:36.468: E/WifiService(1091): Failed to unload Wi-Fi driver.
03-01 00:48:36.492: D/WifiHW(1091): >>> check_driver_loaded
03-01 00:48:36.492: D/WifiHW(1091): Driver is loaded, get wlan.driver.status status: ok
03-01 00:48:36.492: D/WifiHW(1091):   open "/proc/modules"
03-01 00:48:36.492: D/WifiHW(1091): get wlan.driver.status status: unloaded
03-01 00:48:36.492: D/WifiHW(1091): <<< check_driver_loaded
03-01 00:48:36.492: D/WifiHW(1091): >>> insmod, filename= "/system/proprietary/wifi/dhd.ko", args= "firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt"
03-01 00:48:36.492: I/WifiHW(1091): >>> set_wifi_power: 1
03-01 00:48:36.507: I/WifiHW(1091): <<< set_wifi_power
03-01 00:48:37.281: D/Tethering(1091): interfaceAdded: eth0
03-01 00:48:37.281: D/Tethering(1091): isWifi()  regex: wl0.1, iface: eth0
03-01 00:48:37.281: D/Tethering(1091): isUsb()  regex: usb0, iface: eth0
03-01 00:48:37.281: D/Tethering(1091): eth0 is not a tetherable iface, ignoring
03-01 00:48:37.289: D/WifiHW(1091): <<< insmod, ret= 0
03-01 00:48:38.289: D/WifiHW(1091): #### wifi_load_driver, load firmware O.K ####
03-01 00:48:38.289: D/WifiHW(1091): get wlan.driver.status status: ok
03-01 00:48:38.289: D/WifiHW(1091): <<< wifi_load_driver,ok
03-01 00:48:38.289: D/WifiHW(1091): Starting supplicant.......
03-01 00:48:38.289: D/WifiHW(1091): <<< ensure_config_file_exists, access
03-01 00:48:38.289: I/WifiHW(1091):   ++ctl.start <wpa_supplicant>
03-01 00:48:38.289: I/WifiHW(1091):   --ctl.start <wpa_supplicant>
03-01 00:48:38.289: D/WifiHW(1091): Starting supplicant successfully, count: 199
03-01 00:48:38.296: E/WifiHW(1091): Not connected to wpa_supplicant - "BLACKLIST clear" command dropped.
03-01 00:48:38.343: D/WifiHW(1091): Starting connect to supplicant...
03-01 00:48:38.343: D/WifiHW(1091): WIFI_TEST_INTERFACE: "eth0", iface: "eth0"
03-01 00:48:38.343: D/WifiHW(1091): IFACE_DIR: "/data/misc/wifi/sockets", iface: "eth0"
03-01 00:48:38.343: D/WifiHW(1091):   ifname = eth0
03-01 00:48:38.445: D/WifiHW(1091): Retry to wpa_ctrl_open 
03-01 00:48:38.445: D/WifiHW(1091): Connect to supplicant successfully
03-01 00:48:38.445: D/WifiStateTracker(1091): Reset connections and stopping DHCP
03-01 00:48:38.476: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=2 BSSID=00:00:00:00:00:00]
03-01 00:48:39.460: D/WifiStateTracker(1091): Disabling interface
03-01 00:48:39.468: V/WifiMonitor(1091): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-01 00:48:39.468: V/WifiStateTracker(1091): Connection to supplicant established, state=INACTIVE
03-01 00:48:39.484: V/WifiStateTracker(1091): Changing supplicant state: INACTIVE ==> SCANNING
03-01 00:48:39.492: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:48:39.500: V/WifiStateTracker(1091): Changing supplicant state: SCANNING ==> INACTIVE
03-01 00:48:39.523: D/WifiExampleManetService(1569): onReceived: android.net.wifi.SCAN_RESULTS
03-01 00:48:39.562: I/test(1357): supplicant AAAAAAAAAAAaa
03-01 00:48:39.578: D/WifiExampleManetService(1569): Calling Receiver onReceive count: 2
03-01 00:48:39.601: D/WifiExampleManetService(1569): Receiver scan interval limit reached...
03-01 00:48:39.601: I/WifiExampleManetService(1569): 4) Unregistering receiver
03-01 00:48:39.601: I/WifiExampleManetService(1569): 5) Disable Wifi...
03-01 00:48:39.609: D/WifiExampleManetService(1569): Enabling wifi...
03-01 00:48:39.617: I/WifiExampleManetService(1569): Wifi disabled successfully.
03-01 00:48:39.617: I/WifiExampleManetService(1569): 6) Start Manet Manager...
03-01 00:48:39.625: I/ExampleManetObserver(1569): StartAdhocCallable.call()...
03-01 00:48:39.625: D/WifiHW(1091): Enter stop supplicant
03-01 00:48:39.625: I/WifiHW(1091):   ++ctl.stop <wpa_supplicant>
03-01 00:48:39.625: I/WifiHW(1091):   --ctl.stop <wpa_supplicant>
03-01 00:48:39.640: V/WifiMonitor(1091): Event [CTRL-EVENT-TERMINATING - signal 15 received]
03-01 00:48:39.679: D/ManetServiceHelper(1590): Wifi disabled!
03-01 00:48:39.687: I/WifiExampleManetService(1569): Adhoc started successfully.
03-01 00:48:39.687: D/WifiExampleManetService(1569): onReceived: android.net.wifi.SCAN_RESULTS
03-01 00:48:40.656: D/WifiHW(1091): Supplicant have stopped successfully, count: 39

[duhmojo]

Hi jrobble.

Ok, I think I've narrowed it down to a combination of the adhoc binary and the wifi driver/wpa_supplicant when trying to stop adhoc. Do you think you can take a look below and see if there's something that might not be getting cleaned up/performed when disabling adhoc?

I'll spare you the pain of tons of logs and just output the important bits below. I think this is a problem I've experienced in general, but haven't had to look closely at what happens when stopping/starting ManetManager and it gets in a state where it can't re-enable the manet.

Using 2 devices, take one and start a manet using ManetManager, like normal. e.g. touch the wifi icon.

From the 2nd device:

1. Boot the device clean.
2. Make sure Wifi is disabled in settings.
3. USB debug and adb shell onto the device.
4. su
5. cd /data/data/org.span/bin
6. ./adhoc start 1

about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [echo 1 > /proc/sys/net/ipv4/ip_forward]
about to run: [/data/data/org.span/bin/iptables -A FORWARD -j ACCEPT]
about to run: [/data/data/org.span/bin/ifconfig eth0 192.168.1.100 netmask 255.255.255.0]
about to run: [/data/data/org.span/bin/ifconfig eth0 up]
about to run: [/data/data/org.span/bin/iwconfig eth0 mode ad-hoc]
about to run: [/data/data/org.span/bin/iwconfig eth0 essid AndroidAdhoc]
about to run: [/data/data/org.span/bin/iwconfig eth0 channel 1]
about to run: [/data/data/org.span/bin/iwconfig eth0 commit]
script result was []

7. ping the other device

ping -c 1 192.168.1.107
PING 192.168.1.107 (192.168.1.107) 56(84) bytes of data.
64 bytes from 192.168.1.107: icmp_seq=1 ttl=64 time=13.0 ms

OK! Adhoc is enabled. Now to disabled it cleanly.

8. ./adhoc stop 1

about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [/data/data/org.span/bin/ifconfig eth0 down]
script result was []

Nothing eventful. It's assumed that adhoc has been stopped. Logcat only notes the following error related log:

03-01 07:09:10.335: E/Tethering(1091): attempting to remove unknown iface (eth0), ignoring

However, if you try to start adhoc again (see below #9) or go into Wifi Settings and enable Wifi manually, you can get some really funky errors. Wi-Fi will be off. If I try to turn it on, I get the following Logcat entries:

03-01 07:10:26.039: D/WifiHW(1091): Starting connect to supplicant...
03-01 07:10:26.039: D/WifiHW(1091): WIFI_TEST_INTERFACE: "eth0", iface: "eth0"
03-01 07:10:26.039: D/WifiHW(1091): IFACE_DIR: "/data/misc/wifi/sockets", iface: "eth0"
03-01 07:10:26.039: D/WifiHW(1091):   ifname = eth0
03-01 07:10:26.062: E/wpa_supplicant(1959): ioctl[SIOCGIFFLAGS]
03-01 07:10:26.078: E/wpa_supplicant(1959): ioctl[SIOCSIWPMKSA]
03-01 07:10:26.093: E/wpa_supplicant(1959): ioctl[SIOCSIWMODE]
03-01 07:10:26.101: E/wpa_supplicant(1959): ioctl[SIOCGIRANGE]
03-01 07:10:26.125: E/wpa_supplicant(1959): ioctl[SIOCGIWMODE]
03-01 07:10:26.125: E/wpa_supplicant(1959): ioctl[SIOCSIWAP]
03-01 07:10:26.148: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODEEXT]
03-01 07:10:26.148: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODE]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODEEXT]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODE]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODEEXT]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODE]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODEEXT]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODE]
03-01 07:10:26.156: E/wpa_supplicant(1959): Failed to disable WPA in the driver.
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCGIWMODE]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWAP]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCGIFFLAGS]
03-01 07:10:36.054: E/WifiHW(1091): Connecting supplicant error,wpa_ctrl_attach(monitor_conn)error
03-01 07:10:36.054: D/WifiStateTracker(1091): Reset connections and stopping DHCP
03-01 07:10:37.054: D/WifiStateTracker(1091): Disabling interface
03-01 07:10:37.054: E/WifiHW(1091): Not connected to wpa_supplicant - "DRIVER START" command dropped.
03-01 07:10:37.054: E/WifiHW(1091): Not connected to wpa_supplicant - "BLACKLIST clear" command dropped.
03-01 07:10:41.054: D/WifiHW(1091): Starting connect to supplicant...
03-01 07:10:41.054: E/WifiHW(1091): Supplicant not running, cannot connect
03-01 07:10:46.054: D/WifiHW(1091): Starting connect to supplicant...
03-01 07:10:46.054: E/WifiHW(1091): Supplicant not running, cannot connect
03-01 07:10:51.054: D/WifiHW(1091): Starting connect to supplicant...
03-01 07:10:51.054: E/WifiHW(1091): Supplicant not running, cannot connect
03-01 07:10:51.054: V/WifiStateTracker(1091): Supplicant died unexpectedly
03-01 07:10:51.054: D/WifiHW(1091): Starting close supplicant.......
03-01 07:10:51.054: D/WifiStateTracker(1091): Reset connections and stopping DHCP
03-01 07:10:52.062: D/WifiStateTracker(1091): Disabling interface
03-01 07:10:52.062: D/WifiHW(1091): Enter stop supplicant
03-01 07:10:52.062: D/WifiHW(1091): Supplicant have stopped successfully
03-01 07:10:52.062: D/WifiStateTracker(1091): Reset connections and stopping DHCP
03-01 07:10:52.062: W/MessageQueue(1091): null sending message to a Handler on a dead thread
03-01 07:10:52.062: W/MessageQueue(1091): java.lang.RuntimeException: null sending message to a Handler on a dead thread
03-01 07:10:52.062: W/MessageQueue(1091):   at android.os.MessageQueue.enqueueMessage(MessageQueue.java:196)
03-01 07:10:52.062: W/MessageQueue(1091):   at android.os.Looper.quit(Looper.java:192)
03-01 07:10:52.062: W/MessageQueue(1091):   at android.net.wifi.WifiStateTracker.handleMessage(WifiStateTracker.java:1058)
03-01 07:10:52.062: W/MessageQueue(1091):   at android.os.Handler.dispatchMessage(Handler.java:99)
03-01 07:10:52.062: W/MessageQueue(1091):   at android.os.Looper.loop(Looper.java:130)
03-01 07:10:52.062: W/MessageQueue(1091):   at com.android.server.ConnectivityService$ConnectivityThread.run(ConnectivityService.java:236)
03-01 07:10:53.109: D/WifiStateTracker(1091): Disabling interface
03-01 07:10:53.109: D/WifiHW(1091): >>> wifi_unload_driver
03-01 07:10:53.109: D/WifiHW(1091): >>> rmmod
03-01 07:10:53.109: D/WifiHW(1091): Unable to unload driver module "dhd": No such file or directory
03-01 07:10:53.109: I/WifiHW(1091): >>> set_wifi_power: 0
03-01 07:10:53.109: I/WifiHW(1091): <<< set_wifi_power
03-01 07:10:53.218: D/WifiHW(1091): <<< rmmod= -1
03-01 07:10:53.218: E/WifiService(1091): Failed to unload Wi-Fi driver.

The Wi-Fi setting will then display "Error" under "Wi-Fi". I believe the "null sending message to a Handler on a dead thread" exception is from the Setting thread waiting on some system level wifi related call that doesn't successfully complete in time. If I try enabling wifi manually again after the error, it will start successfully. It appears to recover, BUT I've actually had it on occasion crash Android itself.

Here's what happens if you try to start adhoc after stopping it:

9. ./adhoc start 1

about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [echo 1 > /proc/sys/net/ipv4/ip_forward]
about to run: [/data/data/org.span/bin/iptables -A FORWARD -j ACCEPT]
about to run: [/data/data/org.span/bin/ifconfig eth0 192.168.1.100 netmask 255.255.255.0]
error: SIOCSIFADDR (No such device)
about to run: [/data/data/org.span/bin/iwconfig eth0 mode ad-hoc]
Error for wireless request "Set Mode" (8B06) :
    SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 essid AndroidAdhoc]
Error for wireless request "Set ESSID" (8B1A) :
    SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 channel 1]
Error for wireless request "Set Frequency" (8B04) :
    SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 commit]
Error for wireless request "Commit changes" (8B00) :
    SET failed on device eth0 ; No such device.
script result was []

There isn't much I can do with adhoc from this point on. I basically need to toggle Wifi in Setting On and Off, then try adhoc start again.

This kind of coincides with my previous post about having to wait like 2 minutes after stopping ManetManager, before I can start getting wifi scans. If wifi is failing to start correctly after ManetManager stops the manet/adhoc, but it eventually recovers for some reason and I start getting my scans.

I think there might be some system level wifi related issue here, but you're the expert in how to manipulate the system to enable adhoc. Could something be missing from the stop procedure? Or might this be a device or wifi chip manufacturer issue?

Any help is greatly appreciated! Thanks.

[jrobble]

According to your logs, it seems that ad-hoc was cleanly enabled. The
“E/Tethering(1091)” error is probably nothing to worry about.

“Connecting supplicant error,wpa_ctrl_attach(monitor_conn)error” is a real
problem. It seems to be related to properly using the Wi-Fi driver after it
was used by the Manet Manager in ad-hoc mode. One approach would be to
completely unload the Wi-Fi driver when the Manet Manager is done with it.

In adhoc_edify you will notice the following lines for the “stop” action:

# place wifi back under framework control

unload_wifi() && load_wifi();

Try uncommenting them. If that doesn’t work, just try the “unload_wifi()”
part by itself. Note that unlike the "start" action, the "stop" action is
not separated out on a device-by-device basis. You might want to wrap the
lines above in a conditional so that they only get executed for your
specific device.

P.S. I think that the Wi-Fi switch in the Settings apps actually unloads
the Wi-Fi driver (on -> off) and loads the Wi-Fi driver (off -> on) when
it’s toggled.

On Fri, Nov 15, 2013 at 5:30 PM, duhmojo [email protected] wrote:

Hi jrobble.

Ok, I think I've narrowed it down to a combination of the adhoc binary and
the wifi driver/wpa_supplicant when trying to stop adhoc. Do you think you
can take a look below and see if there's something that might not be
getting cleaned up/performed when disabling adhoc?

I'll spare you the pain of tons of logs and just output the important bits
below. I think this is a problem I've experienced in general, but haven't
had to look closely at what happens when stopping/starting ManetManager and
it gets in a state where it can't re-enable the manet.

Using 2 devices, take one and start a manet using ManetManager, like
normal. e.g. touch the wifi icon.

From the 2nd device:

1. Boot the device clean.
2. Make sure Wifi is disabled in settings.
3. USB debug and adb shell onto the device.
4. su
5. cd /data/data/org.span/bin
6. ./adhoc start 1

about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [echo 1 > /proc/sys/net/ipv4/ip_forward]
about to run: [/data/data/org.span/bin/iptables -A FORWARD -j ACCEPT]
about to run: [/data/data/org.span/bin/ifconfig eth0 192.168.1.100 netmask 255.255.255.0]
about to run: [/data/data/org.span/bin/ifconfig eth0 up]
about to run: [/data/data/org.span/bin/iwconfig eth0 mode ad-hoc]
about to run: [/data/data/org.span/bin/iwconfig eth0 essid AndroidAdhoc]
about to run: [/data/data/org.span/bin/iwconfig eth0 channel 1]
about to run: [/data/data/org.span/bin/iwconfig eth0 commit]
script result was []

7. ping the other device

ping -c 1 192.168.1.107
PING 192.168.1.107 (192.168.1.107) 56(84) bytes of data.
64 bytes from 192.168.1.107: icmp_seq=1 ttl=64 time=13.0 ms

OK! Adhoc is enabled. Now to disabled it cleanly.

8. ./adhoc stop 1

about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [/data/data/org.span/bin/ifconfig eth0 down]
script result was []

Nothing eventful. It's assumed that adhoc has been stopped. Logcat only
notes the following error related log:

03-01 07:09:10.335: E/Tethering(1091): attempting to remove unknown iface (eth0), ignoring

However, if you try to start adhoc again (see below #9#9)
or go into Wifi Settings and enable Wifi manually, you can get some really
funky errors. Wi-Fi will be off. If I try to turn it on, I get the
following Logcat entries:

03-01 07:10:26.039: D/WifiHW(1091): Starting connect to supplicant...
03-01 07:10:26.039: D/WifiHW(1091): WIFI_TEST_INTERFACE: "eth0", iface: "eth0"
03-01 07:10:26.039: D/WifiHW(1091): IFACE_DIR: "/data/misc/wifi/sockets", iface: "eth0"
03-01 07:10:26.039: D/WifiHW(1091): ifname = eth0
03-01 07:10:26.062: E/wpa_supplicant(1959): ioctl[SIOCGIFFLAGS]
03-01 07:10:26.078: E/wpa_supplicant(1959): ioctl[SIOCSIWPMKSA]
03-01 07:10:26.093: E/wpa_supplicant(1959): ioctl[SIOCSIWMODE]
03-01 07:10:26.101: E/wpa_supplicant(1959): ioctl[SIOCGIRANGE]
03-01 07:10:26.125: E/wpa_supplicant(1959): ioctl[SIOCGIWMODE]
03-01 07:10:26.125: E/wpa_supplicant(1959): ioctl[SIOCSIWAP]
03-01 07:10:26.148: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODEEXT]
03-01 07:10:26.148: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODE]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODEEXT]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODE]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODEEXT]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODE]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODEEXT]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWENCODE]
03-01 07:10:26.156: E/wpa_supplicant(1959): Failed to disable WPA in the driver.
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCGIWMODE]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCSIWAP]
03-01 07:10:26.156: E/wpa_supplicant(1959): ioctl[SIOCGIFFLAGS]
03-01 07:10:36.054: E/WifiHW(1091): Connecting supplicant error,wpa_ctrl_attach(monitor_conn)error
03-01 07:10:36.054: D/WifiStateTracker(1091): Reset connections and stopping DHCP
03-01 07:10:37.054: D/WifiStateTracker(1091): Disabling interface
03-01 07:10:37.054: E/WifiHW(1091): Not connected to wpa_supplicant - "DRIVER START" command dropped.
03-01 07:10:37.054: E/WifiHW(1091): Not connected to wpa_supplicant - "BLACKLIST clear" command dropped.
03-01 07:10:41.054: D/WifiHW(1091): Starting connect to supplicant...
03-01 07:10:41.054: E/WifiHW(1091): Supplicant not running, cannot connect
03-01 07:10:46.054: D/WifiHW(1091): Starting connect to supplicant...
03-01 07:10:46.054: E/WifiHW(1091): Supplicant not running, cannot connect
03-01 07:10:51.054: D/WifiHW(1091): Starting connect to supplicant...
03-01 07:10:51.054: E/WifiHW(1091): Supplicant not running, cannot connect
03-01 07:10:51.054: V/WifiStateTracker(1091): Supplicant died unexpectedly
03-01 07:10:51.054: D/WifiHW(1091): Starting close supplicant.......
03-01 07:10:51.054: D/WifiStateTracker(1091): Reset connections and stopping DHCP
03-01 07:10:52.062: D/WifiStateTracker(1091): Disabling interface
03-01 07:10:52.062: D/WifiHW(1091): Enter stop supplicant
03-01 07:10:52.062: D/WifiHW(1091): Supplicant have stopped successfully
03-01 07:10:52.062: D/WifiStateTracker(1091): Reset connections and stopping DHCP
03-01 07:10:52.062: W/MessageQueue(1091): null sending message to a Handler on a dead thread
03-01 07:10:52.062: W/MessageQueue(1091): java.lang.RuntimeException: null sending message to a Handler on a dead thread
03-01 07:10:52.062: W/MessageQueue(1091): at android.os.MessageQueue.enqueueMessage(MessageQueue.java:196)
03-01 07:10:52.062: W/MessageQueue(1091): at android.os.Looper.quit(Looper.java:192)
03-01 07:10:52.062: W/MessageQueue(1091): at android.net.wifi.WifiStateTracker.handleMessage(WifiStateTracker.java:1058)
03-01 07:10:52.062: W/MessageQueue(1091): at android.os.Handler.dispatchMessage(Handler.java:99)
03-01 07:10:52.062: W/MessageQueue(1091): at android.os.Looper.loop(Looper.java:130)
03-01 07:10:52.062: W/MessageQueue(1091): at com.android.server.ConnectivityService$ConnectivityThread.run(ConnectivityService.java:236)
03-01 07:10:53.109: D/WifiStateTracker(1091): Disabling interface
03-01 07:10:53.109: D/WifiHW(1091): >>> wifi_unload_driver
03-01 07:10:53.109: D/WifiHW(1091): >>> rmmod
03-01 07:10:53.109: D/WifiHW(1091): Unable to unload driver module "dhd": No such file or directory
03-01 07:10:53.109: I/WifiHW(1091): >>> set_wifi_power: 0
03-01 07:10:53.109: I/WifiHW(1091): <<< set_wifi_power
03-01 07:10:53.218: D/WifiHW(1091): <<< rmmod= -1
03-01 07:10:53.218: E/WifiService(1091): Failed to unload Wi-Fi driver.

The Wi-Fi setting will then display "Error" under "Wi-Fi". I believe the
"null sending message to a Handler on a dead thread" exception is from the
Setting thread waiting on some system level wifi related call that doesn't
successfully complete in time. If I try enabling wifi manually again after
the error, it will start successfully. It appears to recover, BUT I've
actually had it on occasion crash Android itself.

Here's what happens if you try to start adhoc after stopping it:

9. ./adhoc start 1

about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [echo 1 > /proc/sys/net/ipv4/ip_forward]
about to run: [/data/data/org.span/bin/iptables -A FORWARD -j ACCEPT]
about to run: [/data/data/org.span/bin/ifconfig eth0 192.168.1.100 netmask 255.255.255.0]
error: SIOCSIFADDR (No such device)
about to run: [/data/data/org.span/bin/iwconfig eth0 mode ad-hoc]
Error for wireless request "Set Mode" (8B06) :
SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 essid AndroidAdhoc]
Error for wireless request "Set ESSID" (8B1A) :
SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 channel 1]
Error for wireless request "Set Frequency" (8B04) :
SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 commit]
Error for wireless request "Commit changes" (8B00) :
SET failed on device eth0 ; No such device.
script result was []

There isn't much I can do with adhoc from this point on. I basically need
to toggle Wifi in Setting On and Off, then try adhoc start again.

This kind of coincides with my previous post about having to wait like 2
minutes after stopping ManetManager, before I can start getting wifi scans.
If wifi is failing to start correctly after ManetManager stops the
manet/adhoc, but it eventually recovers for some reason and I start getting
my scans.

I think there might be some system level wifi related issue here, but
you're the expert in how to manipulate the system to enable adhoc. Could
something be missing from the stop procedure? Or might this be a device or
wifi chip manufacturer issue?

Any help is greatly appreciated! Thanks.

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/10#issuecomment-28608972
.

[duhmojo]

This should probably get moved to its own issue, but I'll post my follow up here.

I tried uncommenting unload_wifi() && load_wifi() in adhoc_edify, cleaned my MM project, uninstalled MM from my device, then installed it from Eclipse. I shell'ed in and checked that ./conf/adhoc.edify had the change.

From a clean boot:

1. Shell into the device.
2. Start adhoc manually. It starts like normal, like before, as expected and working.
   su
   cd /data/data/org.span/bin
   ./adhoc start 1
3. Try stopping it.
   ./adhoc stop 1

I didn't notice anything from std out that indicated wifi was unloaded and reloaded, but Logcat does:

03-05 22:18:46.890: D/WifiHW(1589): >>> wifi_unload_driver
03-05 22:18:46.890: D/WifiHW(1589): >>> rmmod
03-05 22:18:46.898: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=0 BSSID=00:00:00:00:00:00]
03-05 22:18:46.898: E/Tethering(1106): attempting to remove unknown iface (eth0), ignoring
03-05 22:18:46.898: V/WifiStateTracker(1106): Changing supplicant state: INACTIVE ==> DISCONNECTED
03-05 22:18:46.898: I/test(1440): supplicant AAAAAAAAAAAaa
03-05 22:18:46.898: D/NetdConnector(1106): RCV <- {600 Iface removed eth0}
03-05 22:18:46.906: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-05 22:18:46.906: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd, counter: 1, Maxmum: 30)
03-05 22:18:46.906: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-05 22:18:46.906: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd, counter: 2, Maxmum: 30)
03-05 22:18:47.164: I/WifiHW(1589): >>> set_wifi_power: 0
03-05 22:18:47.164: I/WifiHW(1589): >>> init_rfkill
03-05 22:18:47.164: I/WifiHW(1589):   wlan
03-05 22:18:47.164: I/WifiHW(1589): ��, rfkill_id: 0
03-05 22:18:47.164: I/WifiHW(1589):   rfkill_state_path_wifi: /sys/class/rfkill/rfkill0/state
03-05 22:18:47.164: I/WifiHW(1589): <<< init_rfkill
03-05 22:18:47.164: I/WifiHW(1589): <<< set_wifi_power
03-05 22:18:47.265: D/WifiHW(1589): <<< rmmod= 0
03-05 22:18:47.265: D/WifiHW(1589): >>> check_driver_loaded
03-05 22:18:47.265: D/WifiHW(1589): Driver is loaded, get wlan.driver.status status: ok
03-05 22:18:47.265: D/WifiHW(1589):   open "/proc/modules"
03-05 22:18:47.265: D/WifiHW(1589): get wlan.driver.status status: unloaded
03-05 22:18:47.265: D/WifiHW(1589): <<< check_driver_loaded
03-05 22:18:47.265: D/WifiHW(1589): unload wifi driver successfully, count = 19 (20->0)
03-05 22:18:47.265: D/WifiHW(1589): >>> wifi_load_driver
03-05 22:18:47.265: D/WifiHW(1589): >>> check_driver_loaded
03-05 22:18:47.265: D/WifiHW(1589): Driver is NOT loaded, get wlan.driver.status status: unloaded
03-05 22:18:47.265: D/WifiHW(1589): >>> insmod, filename= "/system/proprietary/wifi/dhd.ko", args= "firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt"
03-05 22:18:47.265: I/WifiHW(1589): >>> set_wifi_power: 1
03-05 22:18:47.265: I/WifiHW(1589): <<< set_wifi_power
03-05 22:18:48.109: D/Tethering(1106): interfaceAdded: eth0
03-05 22:18:48.109: D/Tethering(1106): isWifi()  regex: wl0.1, iface: eth0
03-05 22:18:48.109: D/Tethering(1106): isUsb()  regex: usb0, iface: eth0
03-05 22:18:48.109: D/Tethering(1106): eth0 is not a tetherable iface, ignoring
03-05 22:18:48.109: D/NetdConnector(1106): RCV <- {600 Iface added eth0}
03-05 22:18:48.117: D/WifiHW(1589): <<< insmod, ret= 0
03-05 22:18:49.117: D/WifiHW(1589): #### wifi_load_driver, load firmware O.K ####
03-05 22:18:49.117: D/WifiHW(1589): get wlan.driver.status status: ok
03-05 22:18:49.117: D/WifiHW(1589): <<< wifi_load_driver,ok
03-05 22:18:49.132: E/Tethering(1106): attempting to remove unknown iface (eth0), ignoring
03-05 22:18:49.132: D/NetdConnector(1106): RCV <- {600 Iface removed eth0}
03-05 22:18:49.140: E/wpa_supplicant(1295): ioctl[SIOCSIWPMKSA]
03-05 22:18:49.140: E/wpa_supplicant(1295): ioctl[SIOCGIWSCAN]: 19
03-05 22:18:49.140: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=1 BSSID=00:00:00:00:00:00]
03-05 22:18:49.140: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=0 BSSID=00:00:00:00:00:00]
03-05 22:18:49.140: V/WifiStateTracker(1106): Changing supplicant state: DISCONNECTED ==> INACTIVE
03-05 22:18:49.140: V/WifiStateTracker(1106): Changing supplicant state: INACTIVE ==> DISCONNECTED
03-05 22:18:49.148: I/test(1440): supplicant AAAAAAAAAAAaa
03-05 22:18:49.148: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-05 22:18:49.148: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd, counter: 3, Maxmum: 30)
03-05 22:18:49.148: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-05 22:18:49.148: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd, counter: 4, Maxmum: 30)

Then, similar to my previous post where something seemed to wait/retry/timeout for a couple of minutes before my registered wifi scans would come back, things seem to sort themselves out. Logcat shows this:

03-05 22:19:05.242: V/WifiMonitor(1106): Event [CTRL-EVENT-STATE-CHANGE id=-1 state=2 BSSID=00:00:00:00:00:00]
03-05 22:19:05.242: V/WifiStateTracker(1106): Changing supplicant state: INACTIVE ==> SCANNING
03-05 22:19:05.242: I/test(1440): supplicant AAAAAAAAAAAaa
03-05 22:19:05.249: E/wpa_supplicant(1295): ioctl[SIOCSIWPRIV] (cscan): -1
03-05 22:19:05.249: W/wpa_supplicant(1295): Failed to initiate AP scan.
03-05 22:19:05.249: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd failed (-1): RSSI
03-05 22:19:05.249: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd, counter: 9, Maxmum: 30)
03-05 22:19:05.249: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd failed (-1): LINKSPEED
03-05 22:19:05.249: E/wpa_supplicant(1295): wpa_driver_priv_driver_cmd, counter: 10, Maxmum: 30)

It's repeated for over 2 minutes. It appears to be the OS wifi state tracker trying and trying to scan in the background. The supplicant finally stops and the wifi_unload driver apparently finally unloads. It then is reloaded. I'm assuming the unload and load is all a result of the edify change included, and the actual problem is a deeper driver issue.

03-05 22:21:20.460: D/WifiHW(1106): Enter stop supplicant
03-05 22:21:20.460: I/WifiHW(1106):   ++ctl.stop <wpa_supplicant>
03-05 22:21:20.460: I/WifiHW(1106):   --ctl.stop <wpa_supplicant>
03-05 22:21:20.460: V/WifiMonitor(1106): Event [CTRL-EVENT-TERMINATING - signal 15 received]
03-05 22:21:20.484: E/wpa_supplicant(1295): Failed to disable WPA in the driver.
03-05 22:21:20.523: D/dalvikvm(1227): GC_EXPLICIT freed 169K, 47% free 3215K/6023K, external 12526K/13442K, paused 51ms
03-05 22:21:21.507: E/wpa_supplicant(1295): ioctl[SIOCGIWMODE]
03-05 22:21:21.507: E/wpa_supplicant(1295): ioctl[SIOCSIWAP]
03-05 22:21:21.507: E/wpa_supplicant(1295): ioctl[SIOCGIFFLAGS]
03-05 22:21:21.570: D/WifiHW(1106): Supplicant have stopped successfully, count: 38
03-05 22:21:21.570: D/WifiStateTracker(1106): Reset connections and stopping DHCP
03-05 22:21:21.570: V/WifiStateTracker(1106): Connection to supplicant lost
03-05 22:21:21.570: D/WifiHW(1106): Starting close supplicant.......
03-05 22:21:22.578: D/WifiStateTracker(1106): Disabling interface
03-05 22:21:22.578: D/WifiHW(1106): >>> wifi_unload_driver
03-05 22:21:22.578: D/WifiHW(1106): >>> rmmod
03-05 22:21:22.578: D/WifiHW(1106): Unable to unload driver module "dhd": No such file or directory
03-05 22:21:22.578: I/WifiHW(1106): >>> set_wifi_power: 0
03-05 22:21:22.578: I/WifiHW(1106): <<< set_wifi_power
03-05 22:21:22.679: D/WifiHW(1106): <<< rmmod= -1
03-05 22:21:22.679: E/WifiService(1106): Failed to unload Wi-Fi driver.
03-05 22:21:22.687: D/WifiHW(1106): >>> wifi_load_driver
03-05 22:21:22.687: D/WifiHW(1106): >>> check_driver_loaded
03-05 22:21:22.687: D/WifiHW(1106): Driver is loaded, get wlan.driver.status status: ok
03-05 22:21:22.687: D/WifiHW(1106):   open "/proc/modules"
03-05 22:21:22.695: D/WifiHW(1106): get wlan.driver.status status: unloaded
03-05 22:21:22.695: D/WifiHW(1106): <<< check_driver_loaded
03-05 22:21:22.695: D/WifiHW(1106): >>> insmod, filename= "/system/proprietary/wifi/dhd.ko", args= "firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt"
03-05 22:21:22.695: I/WifiHW(1106): >>> set_wifi_power: 1
03-05 22:21:22.726: I/WifiHW(1106): <<< set_wifi_power
03-05 22:21:23.554: D/Tethering(1106): interfaceAdded: eth0

Any guidance would be helpful. Naturally you've had some great experience with different devices and the plumbing underneath. If there's any manual tests I can try to force the issue, please let me know and I'll give them a whirl ASAP. Thank you!

[duhmojo]

Just a quick note. The Lenovo A1 uses the Broadcom 4329 chip. I noticed in the adhoc.edify there's a rmmod("bcm4329"). Would killing the wpa_supplicant and rmmod'ing bcm4329 force a reload?

I tried combinations of unload_wifi(), kill_process("wpa_supplicant") and load_wifi() but no luck yet. I've also been checking ps inbetween each try for wpa_supplicant.

Generally if I "adhoc start 1" when wifi is in it's broken state I'll get no such device at std out:

about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [echo 1 > /proc/sys/net/ipv4/ip_forward]
about to run: [/data/data/org.span/bin/iptables -A FORWARD -j ACCEPT]
about to run: [/data/data/org.span/bin/ifconfig eth0 192.168.1.104 netmask 255.255.255.0]
error: SIOCSIFADDR (No such device)
about to run: [/data/data/org.span/bin/iwconfig eth0 mode ad-hoc]
Error for wireless request "Set Mode" (8B06) :
    SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 essid AndroidAdhoc]
Error for wireless request "Set ESSID" (8B1A) :
    SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 channel 1]
Error for wireless request "Set Frequency" (8B04) :
    SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 commit]
Error for wireless request "Commit changes" (8B00) :
    SET failed on device eth0 ; No such device.
script result was []

And a notice that the wifi driver is already loaded in Logcat: (this is exactly what appears in Logcat when I adhoc start, nothing more)

03-05 23:19:33.226: D/WifiHW(3427): >>> wifi_load_driver
03-05 23:19:33.226: I/WifiHW(3427): >>> init_rfkill
03-05 23:19:33.226: I/WifiHW(3427):   wlan
03-05 23:19:33.226: I/WifiHW(3427): , rfkill_id: 0
03-05 23:19:33.226: I/WifiHW(3427):   rfkill_state_path_wifi: /sys/class/rfkill/rfkill0/state
03-05 23:19:33.226: I/WifiHW(3427): <<< init_rfkill
03-05 23:19:33.226: D/WifiHW(3427): <<< wifi_load_driver loaded already, wifi power is ON

[jrobble]

Looking at your logs it seems that wpa_supplicant is running before
unloading the Wi-Fi driver. That should not happen. wpa_supplicant should
not be running while you're in ad-hoc mode.

The following line:

module_loaded("bcm4329") && rmmod("bcm4329");

... may work better on some devices with the bcm4329 chip than using
unload_wifi(). I can't say why. You'll have to try it out. Doing so is
heavy-handed, but so is everything else we're doing.

On Sun, Nov 17, 2013 at 9:38 AM, duhmojo [email protected] wrote:

Just a quick note. The Lenovo A1 uses the Broadcom 4329 chip. I noticed in
the adhoc.edify there's a rmmod("bcm4329"). Would killing the
wpa_supplicant and rmmod'ing bcm4329 force a reload?

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/10#issuecomment-28655435
.

[duhmojo]

Thanks for the feedback. I have been able to fix the problem manually by playing around, and I have it also working with adhoc.edify but I'm not sure if this is a clean approach. Maybe you can offer a suggestion. I'd like to add Lenovo A1 device specific support if I can.

1. Clean boot. Wifi is off.
2. Launch ManetManager with the following interesting bits in the adhoc.edify. Note that the A1 is a generic device.

action() == "start" && (
    ...
    # Generic device (e.g. Nexus S 4G)
    (getcfg("device.type") == "generic") && (
        log(load_wifi(), "Loading WiFi driver");

action() == "stop" && (
  getcfg("adhoc.mode") == "wifi" && (
    run_program("/data/data/org.span/bin/ifconfig " +  getcfg("wifi.interface") + " down"); 
    ...
    module_loaded("dhd") && rmmod("dhd");

3. Manually start adhoc. Starts fine. I can ping another device in the manet.

03-09 21:13:21.929: D/WifiHW(1535): >>> wifi_load_driver
03-09 21:13:21.929: I/WifiHW(1535): >>> init_rfkill
03-09 21:13:21.929: I/WifiHW(1535):   wlan
03-09 21:13:21.929: I/WifiHW(1535): , rfkill_id: 0
03-09 21:13:21.929: I/WifiHW(1535):   rfkill_state_path_wifi: /sys/class/rfkill/rfkill0/state
03-09 21:13:21.929: I/WifiHW(1535): <<< init_rfkill
03-09 21:13:21.929: D/WifiHW(1535): >>> check_driver_loaded
03-09 21:13:21.929: D/WifiHW(1535): Driver is NOT loaded, get wlan.driver.status status: 
03-09 21:13:21.929: D/WifiHW(1535): >>> insmod, filename= "/system/proprietary/wifi/dhd.ko", args= "firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt"
03-09 21:13:21.929: I/WifiHW(1535): >>> set_wifi_power: 1
03-09 21:13:21.937: I/WifiHW(1535): <<< set_wifi_power
03-09 21:13:22.851: D/Tethering(1091): interfaceAdded: eth0
03-09 21:13:22.851: D/Tethering(1091): isWifi()  regex: wl0.1, iface: eth0
03-09 21:13:22.851: D/Tethering(1091): isUsb()  regex: usb0, iface: eth0
03-09 21:13:22.851: D/Tethering(1091): eth0 is not a tetherable iface, ignoring
03-09 21:13:22.851: D/NetdConnector(1091): RCV <- {600 Iface added eth0}
03-09 21:13:22.867: D/WifiHW(1535): <<< insmod, ret= 0
03-09 21:13:23.867: D/WifiHW(1535): #### wifi_load_driver, load firmware O.K ####
03-09 21:13:23.867: D/WifiHW(1535): get wlan.driver.status status: ok
03-09 21:13:23.875: D/WifiHW(1535): <<< wifi_load_driver,ok

4. Manually stop adhoc. Stdout displays the usual. Logcat has little to say.

03-09 21:20:00.804: E/Tethering(1091): attempting to remove unknown iface (eth0), ignoring
03-09 21:20:00.804: D/NetdConnector(1091): RCV <- {600 Iface removed eth0}

5. Try re-starting it manually fails, as discussed. Here's stdout:

about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [echo 1 > /proc/sys/net/ipv4/ip_forward]
about to run: [/data/data/org.span/bin/iptables -A FORWARD -j ACCEPT]
about to run: [/data/data/org.span/bin/ifconfig eth0 192.168.1.104 netmask 255.255.255.0]
error: SIOCSIFADDR (No such device)
about to run: [/data/data/org.span/bin/iwconfig eth0 mode ad-hoc]
Error for wireless request "Set Mode" (8B06) :
    SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 essid AndroidAdhoc]
Error for wireless request "Set ESSID" (8B1A) :
    SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 channel 1]
Error for wireless request "Set Frequency" (8B04) :
    SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 commit]
Error for wireless request "Commit changes" (8B00) :
    SET failed on device eth0 ; No such device.
script result was []

Here's Logcat:

03-09 21:21:08.171: D/WifiHW(2059): >>> wifi_load_driver
03-09 21:21:08.171: I/WifiHW(2059): >>> init_rfkill
03-09 21:21:08.179: I/WifiHW(2059):   wlan
03-09 21:21:08.179: I/WifiHW(2059): , rfkill_id: 0
03-09 21:21:08.179: I/WifiHW(2059):   rfkill_state_path_wifi: /sys/class/rfkill/rfkill0/state
03-09 21:21:08.179: I/WifiHW(2059): <<< init_rfkill
03-09 21:21:08.179: D/WifiHW(2059): <<< wifi_load_driver loaded already, wifi power is ON

6. NOW! If I try to manually insmod the dhd.ko driver after stopping adhoc, it fixes the wifi driver. Wifi can be enabled as normal, and you can alternatively restart adhoc! After restarting adhoc I can once again ping the other device.

# insmod /system/proprietary/wifi/dhd.ko firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt

# ./adhoc start 1
about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [echo 1 > /proc/sys/net/ipv4/ip_forward]
about to run: [/data/data/org.span/bin/iptables -A FORWARD -j ACCEPT]
about to run: [/data/data/org.span/bin/ifconfig eth0 192.168.1.104 netmask 255.255.255.0]
about to run: [/data/data/org.span/bin/ifconfig eth0 up]
about to run: [/data/data/org.span/bin/iwconfig eth0 mode ad-hoc]
about to run: [/data/data/org.span/bin/iwconfig eth0 essid AndroidAdhoc]
about to run: [/data/data/org.span/bin/iwconfig eth0 channel 1]
about to run: [/data/data/org.span/bin/iwconfig eth0 commit]
script result was []

I tried modifying the adhoc.edify to automate this by adding the insmod to stop. What do you think? I would assume we need wifi workable after ManetManager actually stops and not fix it only when it starts up, or you fiddle with the Wifi setting.

action() == "stop" && (
  ...
  getcfg("adhoc.mode") == "wifi" && (
    run_program("/data/data/org.span/bin/ifconfig " +  getcfg("wifi.interface") + " down"); 
    ...    
#    # place wifi back under framework control
#    unload_wifi() && load_wifi();
    ...
    module_loaded("dhd") && rmmod("dhd");
    log(insmod("/system/proprietary/wifi/dhd.ko", "firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt"), "Loading dhd.ko module");

[jrobble]

I'm glad you found a solution.

Insmodding the driver module when stopping ad-hoc mode will re-enable the
normal Wi-Fi under the hood. If the normal Wi-Fi was enabled before
starting ad-hoc mode then that's desirable. If it wasn't then it's not. You
could keep track of the previous Wi-Fi state and make a decision based on
that.

Also, in addition to insmodding do you need to restart the wpa_supplicant?

Manually insmodding will not flip the Wi-Fi switch in the Settings app.,
which might confuse users. Basically you're working below the Android
framework. The Wi-Fi notification icon probably doesn't show up either.
On Nov 21, 2013 8:34 AM, "duhmojo" [email protected] wrote:

Thanks for the feedback. I have been able to fix the problem manually by
playing around, but I can't get it working via adhoc.edify. Maybe you can
offer a suggestion. I'd like to add Lenovo A1 device specific support if I
can.

1. Clean boot. Wifi is off.
2. Launch ManetManager with the following interesting bits in the
   adhoc.edify. Note that the A1 is a generic device.

action() == "start" && (
...
# Generic device (e.g. Nexus S 4G)
(getcfg("device.type") == "generic") && (
log(load_wifi(), "Loading WiFi driver");

action() == "stop" && (
getcfg("adhoc.mode") == "wifi" && (
run_program("/data/data/org.span/bin/ifconfig " + getcfg("wifi.interface") + " down");
...
module_loaded("dhd") && rmmod("dhd");

3. Manually start adhoc. Starts fine. I can ping another device in the
   manet.

03-09 21:13:21.929: D/WifiHW(1535): >>> wifi_load_driver
03-09 21:13:21.929: I/WifiHW(1535): >>> init_rfkill
03-09 21:13:21.929: I/WifiHW(1535): wlan
03-09 21:13:21.929: I/WifiHW(1535): , rfkill_id: 0
03-09 21:13:21.929: I/WifiHW(1535): rfkill_state_path_wifi: /sys/class/rfkill/rfkill0/state
03-09 21:13:21.929: I/WifiHW(1535): <<< init_rfkill
03-09 21:13:21.929: D/WifiHW(1535): >>> check_driver_loaded
03-09 21:13:21.929: D/WifiHW(1535): Driver is NOT loaded, get wlan.driver.status status:
03-09 21:13:21.929: D/WifiHW(1535): >>> insmod, filename= "/system/proprietary/wifi/dhd.ko", args= "firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt"
03-09 21:13:21.929: I/WifiHW(1535): >>> set_wifi_power: 1
03-09 21:13:21.937: I/WifiHW(1535): <<< set_wifi_power
03-09 21:13:22.851: D/Tethering(1091): interfaceAdded: eth0
03-09 21:13:22.851: D/Tethering(1091): isWifi() regex: wl0.1, iface: eth0
03-09 21:13:22.851: D/Tethering(1091): isUsb() regex: usb0, iface: eth0
03-09 21:13:22.851: D/Tethering(1091): eth0 is not a tetherable iface, ignoring
03-09 21:13:22.851: D/NetdConnector(1091): RCV <- {600 Iface added eth0}
03-09 21:13:22.867: D/WifiHW(1535): <<< insmod, ret= 0
03-09 21:13:23.867: D/WifiHW(1535): #### wifi_load_driver, load firmware O.K ####
03-09 21:13:23.867: D/WifiHW(1535): get wlan.driver.status status: ok
03-09 21:13:23.875: D/WifiHW(1535): <<< wifi_load_driver,ok

4. Manually stop adhoc. Stdout displays the usual. Logcat has little to
   say.

03-09 21:20:00.804: E/Tethering(1091): attempting to remove unknown iface (eth0), ignoring
03-09 21:20:00.804: D/NetdConnector(1091): RCV <- {600 Iface removed eth0}

5. Try re-starting it manually fails, as discussed. Here's stdout:

about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [echo 1 > /proc/sys/net/ipv4/ip_forward]
about to run: [/data/data/org.span/bin/iptables -A FORWARD -j ACCEPT]
about to run: [/data/data/org.span/bin/ifconfig eth0 192.168.1.104 netmask 255.255.255.0]
error: SIOCSIFADDR (No such device)
about to run: [/data/data/org.span/bin/iwconfig eth0 mode ad-hoc]
Error for wireless request "Set Mode" (8B06) :
SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 essid AndroidAdhoc]
Error for wireless request "Set ESSID" (8B1A) :
SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 channel 1]
Error for wireless request "Set Frequency" (8B04) :
SET failed on device eth0 ; No such device.
about to run: [/data/data/org.span/bin/iwconfig eth0 commit]
Error for wireless request "Commit changes" (8B00) :
SET failed on device eth0 ; No such device.
script result was []

Here's Logcat:

03-09 21:21:08.171: D/WifiHW(2059): >>> wifi_load_driver
03-09 21:21:08.171: I/WifiHW(2059): >>> init_rfkill
03-09 21:21:08.179: I/WifiHW(2059): wlan
03-09 21:21:08.179: I/WifiHW(2059): , rfkill_id: 0
03-09 21:21:08.179: I/WifiHW(2059): rfkill_state_path_wifi: /sys/class/rfkill/rfkill0/state
03-09 21:21:08.179: I/WifiHW(2059): <<< init_rfkill
03-09 21:21:08.179: D/WifiHW(2059): <<< wifi_load_driver loaded already, wifi power is ON

6. NOW! If I try to manually insmod the dhd.ko driver after stopping
   adhoc, it fixes the wifi driver. Wifi can be enabled as normal, and you can
   alternatively restart adhoc! After restarting adhoc I can once again ping
   the other device.

insmod /system/proprietary/wifi/dhd.ko firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt

./adhoc start 1

about to run: [/data/data/org.span/bin/iptables -t filter -F]
about to run: [/data/data/org.span/bin/iptables -t nat -F]
about to run: [echo 1 > /proc/sys/net/ipv4/ip_forward]
about to run: [/data/data/org.span/bin/iptables -A FORWARD -j ACCEPT]
about to run: [/data/data/org.span/bin/ifconfig eth0 192.168.1.104 netmask 255.255.255.0]
about to run: [/data/data/org.span/bin/ifconfig eth0 up]
about to run: [/data/data/org.span/bin/iwconfig eth0 mode ad-hoc]
about to run: [/data/data/org.span/bin/iwconfig eth0 essid AndroidAdhoc]
about to run: [/data/data/org.span/bin/iwconfig eth0 channel 1]
about to run: [/data/data/org.span/bin/iwconfig eth0 commit]
script result was []

I tried modifying the adhoc.edify to automate this by adding the insmod to
stop. What do you think? I would assume we need wifi workable after
ManetManager actually stops and not fix it only when it starts up, or you
fiddle with the Wifi setting.

action() == "stop" && (
...
getcfg("adhoc.mode") == "wifi" && (
run_program("/data/data/org.span/bin/ifconfig " + getcfg("wifi.interface") + " down");
...

# place wifi back under framework control

unload_wifi() && load_wifi();

...
module_loaded("dhd") && rmmod("dhd");
log(insmod("/system/proprietary/wifi/dhd.ko", "firmware_path=/system/proprietary/wifi/rtecdc.bin nvram_path=/system/proprietary/wifi/nvram.txt"), "Loading dhd.ko module");

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/10#issuecomment-28999526
.

[duhmojo]

I have to think about this, but I/we need wifi off before adhoc is enabled. (in manual testing) I didn't think MM touched the Wifi Settings from the OS level. If not, then wouldn't it be the MM Java app that would track if Wifi was enabled, disabled it, do it's adhoc/olsr execution, and when stopping, turn wifi back on? I assumed that would happen after the adhoc/adhoc.edify was executed. Right now, with the little I've done, wifi is off before adhoc/manet. When I stop the manet, wifi is still off.

I don't have to restart wpa_supplicant. I looks as if insmod results in wpa_supplicant being loaded.

[jrobble]

Right Wi-Fi needs to be off before starting ad-hoc mode using MM. We could
program the MM to turn it off.

I think the edify load_wifi() and unload_wifi() calls affect the OS and
therefore the Settings app. MM can set properties that are used by the
edify script to determine if normal Wi-Fi should be re-enabled or not.
On Nov 21, 2013 10:50 AM, "duhmojo" [email protected] wrote:

I have to think about this, but I/we need wifi off before adhoc is enabled.
(in manual testing) I didn't think MM touched the Wifi Settings from the OS
level. If not, then wouldn't it be the MM Java app that would track if Wifi
was enabled, disabled it, do it's adhoc/olsr execution, and when stopping,
turn wifi back on? I assumed that would happen after the adhoc/adhoc.edify
was executed. Right now, with the little I've done, wifi is off before
adhoc/manet. When I stop the manet, wifi is still off.

I don't have to restart wpa_supplicant. I looks as if insmod results in
wpa_supplicant being loaded.

—
Reply to this email directly or view it on
GitHubhttps://github.com//issues/10#issuecomment-29011958
.