RoboSpice: onSuccessRequest never called

[FastCode85]

It's my first post here on GitHub.
I'm using RoboSpice for an Android Application. The problem is that using a certain service the onRequestSuccess of my RequestListener is never called. The strange thing is that if i set a bad API url on my requesting method ( the overridden loadDataFromNetwork() ) the onRequestFailure is called. Trying this code with another web service gives no problem.

Here are the classes, followed by the application's Logcat. Please note that by using a REST client such Fiddler i get a response. MainActivity

import android.app.Activity;

import android.content.Context;
import android.os.Bundle;
import android.text.TextUtils;
import android.util.Log;
import android.view.View;
import android.view.Window;
import android.view.inputmethod.InputMethodManager;

import android.widget.Button;
import android.widget.EditText;
import android.widget.LinearLayout;
import android.widget.ListView;
import android.widget.TextView;
import android.widget.Toast;

import org.springframework.web.client.RestTemplate;

import com.octo.android.robospice.JacksonSpringAndroidSpiceService;
import com.octo.android.robospice.SpiceManager;
import com.octo.android.robospice.persistence.DurationInMillis;
import com.octo.android.robospice.persistence.exception.SpiceException;
import com.octo.android.robospice.request.listener.RequestListener;
import primoandroidmaven.myrobo.R;
import primoandroidmaven.myrobo.model.FakeApiRequest;
import primoandroidmaven.myrobo.model.ShortURLResponse;

public class MainActivity extends Activity {

private static final String KEY_LAST_REQUEST_CACHE_KEY = "lastRequestCacheKey";

private SpiceManager spiceManager = new SpiceManager(
    JacksonSpringAndroidSpiceService.class);



private String lastRequestCacheKey;

@Override
public void onCreate(Bundle savedInstanceState) {
    super.onCreate(savedInstanceState);
    requestWindowFeature(Window.FEATURE_INDETERMINATE_PROGRESS);
    setContentView(R.layout.main);

    initUIComponents();
}

@Override
protected void onStart() {
    spiceManager.start(this);
    super.onStart();
}

@Override
protected void onStop() {
    spiceManager.shouldStop();
    super.onStop();
}

private void initUIComponents() {
    Button shortenButton = (Button) findViewById(R.id.shorten_button);
    final EditText searchQuery = (EditText) findViewById(R.id.url_edittext);



    shortenButton.setOnClickListener(new View.OnClickListener() {

        public void onClick(View view) {
            performRequest(searchQuery.getText().toString());
            // clear focus
            LinearLayout linearLayout = (LinearLayout) findViewById(R.id.search_layout);
            linearLayout.requestFocus();
            // hide keyboard
            InputMethodManager imm = (InputMethodManager) getSystemService(Context.INPUT_METHOD_SERVICE);
            imm.hideSoftInputFromWindow(searchQuery.getWindowToken(), 0);
        }
    });
}

private void performRequest(String user) {
    MainActivity.this.setProgressBarIndeterminateVisibility(true);
    ShortenRequest request = new ShortenRequest();
    lastRequestCacheKey = request.createCacheKey();
    spiceManager.execute(request, lastRequestCacheKey,
        DurationInMillis.ONE_MINUTE, new  ShortenRequestListener());
}

@Override
protected void onSaveInstanceState(Bundle outState) {
    Log.i("TEST","bbbbbbb REQUEST");
    if (!TextUtils.isEmpty(lastRequestCacheKey)) {
        outState.putString(KEY_LAST_REQUEST_CACHE_KEY, lastRequestCacheKey);
    }
    super.onSaveInstanceState(outState);
}

@Override
protected void onRestoreInstanceState(Bundle savedInstanceState) {
    super.onRestoreInstanceState(savedInstanceState);
    Log.i("TEST","aaaaa REQUEST");
    if (savedInstanceState.containsKey(KEY_LAST_REQUEST_CACHE_KEY)) {
        lastRequestCacheKey = savedInstanceState.getString(KEY_LAST_REQUEST_CACHE_KEY);
        spiceManager.addListenerIfPending(ShortURLResponse.class, lastRequestCacheKey, new ShortenRequestListener());
        spiceManager.getFromCache(ShortURLResponse.class,lastRequestCacheKey, DurationInMillis.ONE_MINUTE,
            new ShortenRequestListener());
    }
}

private class ShortenRequestListener implements
    RequestListener<ShortURLResponse> {



    public void onRequestFailure(SpiceException e) {
        Log.i("TEST","BAD REQUEST");
        Toast.makeText(MainActivity.this,
            "Error during request: " + e.getLocalizedMessage(), Toast.LENGTH_LONG)
            .show();
        MainActivity.this.setProgressBarIndeterminateVisibility(false);
    }


    //successo, metodo di callback
    public void onRequestSuccess(ShortURLResponse listFollowers) {

        Log.i("TEST",listFollowers.getTinyurl());
        TextView v=(TextView)findViewById(R.id.url_edittext);
        v.setText(listFollowers.getTinyurl());
        Log.i("TEST",listFollowers.getTinyurl());
        MainActivity.this.setProgressBarIndeterminateVisibility(false);
    }
}

}

ShortenRequest.java

import primoandroidmaven.myrobo.model.ShortURLRequest;
import primoandroidmaven.myrobo.model.ShortURLResponse;

import java.util.HashMap;

import com.octo.android.robospice.request.springandroid.SpringAndroidSpiceRequest;

import android.util.Log;

public class ShortenRequest extends SpringAndroidSpiceRequest {

private static String apiKey="0aad1359-9212-4d0e-8df2-55d07ab65c34";

public ShortenRequest() {
    super(ShortURLResponse.class);
}


@Override
public ShortURLResponse loadDataFromNetwork() throws Exception {

    ShortURLRequest shortURL=new ShortURLRequest();
    shortURL.setUsername("Mdev");
    shortURL.setApikey(apiKey);
    shortURL.setFullurl("https://it.yahoo.com");
    shortURL.setTinylength(15);
    shortURL.setAdenable(false);
    String url = "https://aci.do/api/acidoapi.svc/ShortUrl";


    Log.i("TEST","CALLING");
    ShortURLResponse resp=(ShortURLResponse)getRestTemplate().postForObject(url, shortURL,ShortURLResponse.class);
    Log.i("TEST","Called. Result: "+resp.getError()+" - "+resp.getResult());
    return resp;
}

/**
 * This method generates a unique cache key for this request. In this case
 * our cache key depends just on the keyword.
 * @return
 */
public String createCacheKey() {
    return "followers.short";
}

}

ShortURLRequest.java

public class ShortURLRequest{

private String username;
private String apikey;
private String fullurl;
private int tinylength;
public String getUsername() {
    return username;
}

public void setUsername(String username) {
    this.username = username;
}

public String getApikey() {
    return apikey;
}

public void setApikey(String apikey) {
    this.apikey = apikey;
}

public String getFullurl() {
    return fullurl;
}

public void setFullurl(String fullurl) {
    this.fullurl = fullurl;
}

public int getTinylength() {
    return tinylength;
}

public void setTinylength(int tinylength) {
    this.tinylength = tinylength;
}

public boolean isAdenable() {
    return adenable;
}

public void setAdenable(boolean adenable) {
    this.adenable = adenable;
}

private boolean adenable;

public ShortURLRequest(){

}

}

ShortURLResponse.java

import org.codehaus.jackson.annotate.JsonIgnoreProperties;

@JsonIgnoreProperties(ignoreUnknown = true)
public class ShortURLResponse{

private int result;
private String error;
private String tinyurl;
private String fullurl;
private boolean adenable;
private int tsgeneration;

public ShortURLResponse(){

}

public int getResult() {
    return result;
}

public void setResult(int result) {
    this.result = result;
}

public String getError() {
    return error;
}

public void setError(String error) {
    this.error = error;
}

public String getTinyurl() {
    return tinyurl;
}

public void setTinyurl(String tinyurl) {
    this.tinyurl = tinyurl;
}

public String getFullurl() {
    return fullurl;
}

public void setFullurl(String fullurl) {
    this.fullurl = fullurl;
}

public boolean isAdenable() {
    return adenable;
}

public void setAdenable(boolean adenable) {
    this.adenable = adenable;
}

public int getTsgeneration() {
    return tsgeneration;
}

public void setTsgeneration(int tsgeneration) {
    this.tsgeneration = tsgeneration;
}

}

Logcat

11-26 10:11:51.469: D//SpiceManager.java:489(7206): 10:11:51.481 main adding request to request queue
11-26 10:11:51.489: D//SpiceManager.java:286(7206): 10:11:51.491 SpiceManagerThread 6 Sending request to service : CachedSpiceRequest
11-26 10:11:51.509: D//RequestProcessor.java:63(7206): 10:11:51.507 SpiceManagerThread 6 Adding request to queue 1100623720: CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@418b14e8] size is 0
11-26 10:11:51.529: D//RequestProcessor.java:85(7206): 10:11:51.528 SpiceManagerThread 6 Adding entry for type class primoandroidmaven.myrobo.model.ShortURLResponse and cacheKey followers.short.
11-26 10:11:51.529: D//RequestProgressManager.java:61(7206): 10:11:51.542 SpiceManagerThread 6 Request was added to queue.
11-26 10:11:51.539: D//SpiceServiceListenerNotifier.java:146(7206): 10:11:51.547 SpiceManagerThread 6 Message queue is Handler (android.os.Handler) {41957428}
11-26 10:11:51.549: D//SpiceServiceListenerNotifier.java:175(7206): 10:11:51.553 main Processing request added: CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@418b14e8]
11-26 10:11:51.549: D//RequestProgressManager.java:82(7206): 10:11:51.560 SpiceManagerThread 6 Sending progress PENDING
11-26 10:11:51.559: D//SpiceServiceListenerNotifier.java:146(7206): 10:11:51.567 SpiceManagerThread 6 Message queue is Handler (android.os.Handler) {41957428}
11-26 10:11:51.579: V//DefaultRequestListenerNotifier.java:131(7206): 10:11:51.589 main Notifying 1 listeners of progress com.octo.android.robospice.request.listener.RequestProgress@41967c18
11-26 10:11:51.599: D//DefaultRequestRunner.java:83(7206): 10:11:51.582 Thread-2530 Processing request : CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@418b14e8]
11-26 10:11:51.599: V//SpiceService.java:506(7206): 10:11:51.583 SpiceManagerThread 6 Pending requests : 1
11-26 10:11:51.619: D//DefaultRequestRunner.java:97(7206): 10:11:51.623 Thread-2530 Loading request from cache : CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@418b14e8]
11-26 10:11:51.639: V//SpiceService.java:508(7206): 10:11:51.631 SpiceManagerThread 6 Stop foreground
11-26 10:11:51.639: D//RequestProgressManager.java:82(7206): 10:11:51.643 Thread-2530 Sending progress READING_FROM_CACHE
11-26 10:11:51.649: D//SpiceServiceListenerNotifier.java:146(7206): 10:11:51.658 Thread-2530 Message queue is Handler (android.os.Handler) {41957428}
11-26 10:11:51.679: V//DefaultRequestListenerNotifier.java:131(7206): 10:11:51.682 main Notifying 1 listeners of progress com.octo.android.robospice.request.listener.RequestProgress@418eb818
11-26 10:11:51.799: D//DefaultRequestRunner.java:103(7206): 10:11:51.810 Thread-2530 Request loaded from cache : CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@418b14e8] result=primoandroidmaven.myrobo.model.ShortURLResponse@418947b8
11-26 10:11:54.712: D//RequestProgressManager.java:82(7206): 10:11:54.707 Thread-2530 Sending progress COMPLETE
11-26 10:11:54.722: D//SpiceServiceListenerNotifier.java:146(7206): 10:11:54.724 Thread-2530 Message queue is Handler (android.os.Handler) {41957428}
11-26 10:11:54.732: D//SpiceServiceListenerNotifier.java:146(7206): 10:11:54.739 Thread-2530 Message queue is Handler (android.os.Handler) {41957428}
11-26 10:11:54.752: V//DefaultRequestListenerNotifier.java:131(7206): 10:11:54.749 main Notifying 1 listeners of progress com.octo.android.robospice.request.listener.RequestProgress@41988c58
11-26 10:11:54.762: V//RequestProgressManager.java:161(7206): 10:11:54.756 Thread-2530 Removing CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@418b14e8] size is 1
11-26 10:11:54.772: D//RequestProgressManager.java:91(7206): 10:11:54.773 Thread-2530 Sending all request complete.
11-26 10:11:54.782: V//DefaultRequestListenerNotifier.java:166(7206): 10:11:54.779 main Notifying 1 listeners of request success
11-26 10:11:54.792: V//SpiceService.java:495(7206): 10:11:54.792 Thread-2530 Pending requests : 0
11-26 10:11:54.792: V//DefaultRequestListenerNotifier.java:172(7206): 10:11:54.794 main Notifying ShortenRequestListener
11-26 10:11:54.802: D//SpiceServiceListenerNotifier.java:146(7206): 10:11:54.807 Thread-2530 Message queue is Handler (android.os.Handler) {41957428}
11-26 10:11:54.812: D//DefaultRequestRunner.java:295(7206): 10:11:54.819 Thread-2530 It tooks 3238 ms to process request CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@418b14e8].
11-26 10:12:21.558: I/TEST(7206): bbbbbbb REQUEST
11-26 10:12:21.558: D//SpiceManager.java:326(7206): 10:12:21.574 main SpiceManager stopping. Joining
11-26 10:12:21.568: V//SpiceManager.java:767(7206): 10:12:21.576 main Cleared listeners of all requests to launch
11-26 10:12:21.578: V//SpiceManager.java:796(7206): 10:12:21.587 main Cleared listeners of all pending requests
11-26 10:12:21.578: D//SpiceManager.java:265(7206): 10:12:21.591 SpiceManagerThread 6 Interrupted while waiting for new request.
11-26 10:12:21.598: D/dalvikvm(7206): GC_CONCURRENT freed 447K, 14% free 9236K/10716K, paused 2ms+10ms, total 44ms
11-26 10:12:21.608: D//SpiceManager.java:271(7206): 10:12:21.616 SpiceManagerThread 6 SpiceManager request runner terminated. Requests count: 0, stopped true, interrupted false
11-26 10:12:21.608: D//SpiceManager.java:339(7206): 10:12:21.618 main Runner join time (ms) when should stop 29
11-26 10:12:21.608: V//SpiceManager.java:1221(7206): 10:12:21.619 main Unbinding from service start.
11-26 10:12:21.608: V//SpiceManager.java:1225(7206): 10:12:21.620 main Unbinding from service.
11-26 10:12:21.608: D//SpiceManager.java:1227(7206): 10:12:21.623 main Unbound from service : JacksonSpringAndroidSpiceService
11-26 10:12:21.618: D//SpiceManager.java:345(7206): 10:12:21.625 main SpiceManager stopped.
11-26 10:12:21.628: V//SpiceService.java:506(7206): 10:12:21.634 main Pending requests : 0
11-26 10:12:21.628: V//SpiceService.java:508(7206): 10:12:21.636 main Stop foreground
11-26 10:12:21.628: V//SpiceService.java:495(7206): 10:12:21.639 main Pending requests : 0
11-26 10:12:21.638: D//SpiceService.java:303(7206): 10:12:21.645 main SpiceService instance destroyed.
11-26 10:12:34.180: D//SpiceManager.java:212(7206): 10:12:34.193 main SpiceManager started.
11-26 10:12:34.210: D//SpiceService.java:134(7206): 10:12:34.222 main SpiceService instance created.
11-26 10:12:34.240: V//SpiceManager.java:1191(7206): 10:12:34.246 SpiceManagerThread 7 Binding to service.
11-26 10:12:34.250: V//SpiceManager.java:1197(7206): 10:12:34.256 SpiceManagerThread 7 Binding to service succeeded.
11-26 10:12:34.250: V//SpiceService.java:506(7206): 10:12:34.257 main Pending requests : 0
11-26 10:12:34.250: V//SpiceService.java:508(7206): 10:12:34.259 main Stop foreground
11-26 10:12:34.250: D//SpiceServiceListenerNotifier.java:33(7206): 10:12:34.263 main Message Queue starting
11-26 10:12:34.250: D//SpiceManager.java:1088(7206): 10:12:34.264 main Bound to service : JacksonSpringAndroidSpiceService
11-26 10:12:34.271: D//SpiceManager.java:1245(7206): 10:12:34.275 SpiceManagerThread 7 Waiting for service to be bound.
11-26 10:12:34.281: D//SpiceManager.java:1252(7206): 10:12:34.280 SpiceManagerThread 7 Bound ok.
11-26 10:12:34.301: D/WritingBuddyImpl(7206): getCurrentWritingBuddyView()
11-26 10:12:35.622: D/HAWAII_EGL(7206): eglMakeCurrent(0x40c7c048, 0x40cd8258, 0x40cd8258) Thread: 7206
11-26 10:12:35.622: D/HAWAII_EGL(7206): eglMakeCurrent(NULL) Thread: 7206
11-26 10:12:35.642: D/HAWAII_EGL(7206): eglMakeCurrent(0x40c7c048, 0x494a7a98, 0x494a7a98) Thread: 7206
11-26 10:12:35.792: D/HAWAII_EGL(7206): eglMakeCurrent(NULL) Thread: 7206
11-26 10:12:35.792: D/HAWAII_EGL(7206): eglDestroySurface() surface: 0x494a7a98, android window 0x494a89b8, Thread: 7206
11-26 10:12:36.062: I/TEST(7206): bbbbbbb REQUEST
11-26 10:12:36.062: D//SpiceManager.java:326(7206): 10:12:36.069 main SpiceManager stopping. Joining
11-26 10:12:36.062: V//SpiceManager.java:767(7206): 10:12:36.070 main Cleared listeners of all requests to launch
11-26 10:12:36.062: V//SpiceManager.java:796(7206): 10:12:36.071 main Cleared listeners of all pending requests
11-26 10:12:36.072: D//SpiceManager.java:265(7206): 10:12:36.075 SpiceManagerThread 7 Interrupted while waiting for new request.
11-26 10:12:36.072: D//SpiceManager.java:271(7206): 10:12:36.077 SpiceManagerThread 7 SpiceManager request runner terminated. Requests count: 0, stopped true, interrupted false
11-26 10:12:36.072: D//SpiceManager.java:339(7206): 10:12:36.079 main Runner join time (ms) when should stop 6
11-26 10:12:36.072: V//SpiceManager.java:1221(7206): 10:12:36.080 main Unbinding from service start.
11-26 10:12:36.082: V//SpiceManager.java:1225(7206): 10:12:36.081 main Unbinding from service.
11-26 10:12:36.082: D//SpiceManager.java:1227(7206): 10:12:36.089 main Unbound from service : JacksonSpringAndroidSpiceService
11-26 10:12:36.082: D//SpiceManager.java:345(7206): 10:12:36.090 main SpiceManager stopped.
11-26 10:12:36.082: V//SpiceService.java:506(7206): 10:12:36.092 main Pending requests : 0
11-26 10:12:36.082: V//SpiceService.java:508(7206): 10:12:36.093 main Stop foreground
11-26 10:12:36.082: V//SpiceService.java:495(7206): 10:12:36.094 main Pending requests : 0
11-26 10:12:36.092: D//SpiceService.java:303(7206): 10:12:36.102 main SpiceService instance destroyed.
11-26 10:12:40.026: D/ProgressBar(8389): setProgress = 0
11-26 10:12:40.026: D/ProgressBar(8389): setProgress = 0, fromUser = false
11-26 10:12:40.026: D/ProgressBar(8389): mProgress = 0mIndeterminate = false, mMin = 0, mMax = 100
11-26 10:12:40.046: D//SpiceManager.java:212(8389): 10:12:40.056 main SpiceManager started.
11-26 10:12:40.056: V//SpiceManager.java:1191(8389): 10:12:40.071 SpiceManagerThread 0 Binding to service.
11-26 10:12:40.066: V//SpiceManager.java:1197(8389): 10:12:40.073 SpiceManagerThread 0 Binding to service succeeded.
11-26 10:12:40.066: D//SpiceManager.java:1245(8389): 10:12:40.084 SpiceManagerThread 0 Waiting for service to be bound.
11-26 10:12:40.116: D/libEGL(8389): loaded /system/lib/egl/libGLES_hawaii.so
11-26 10:12:40.116: D/(8389): mem_init ++
11-26 10:12:40.116: D/(8389): gHwMemAllocator client 3
11-26 10:12:40.116: D/(8389): **** Using ION allocator ****
11-26 10:12:40.116: D/(8389): registered SIGUSR1[10] for pid[8389]
11-26 10:12:40.116: D/(8389): HwMemAllocatorImpl Static Counters 0 0
11-26 10:12:40.116: D/(8389): HwMemAllocatorImpl[4922cdcc] totalDeviceAllocSize[0] totalFree[0] maxFree[0] in numSlabs[0]
11-26 10:12:40.116: D/(8389): mem_init 4922cdcc--
11-26 10:12:40.126: D/ION(8389): config: version(0x10000) secure(0xf000) 256M(0x22d) fast(0x608) hwwr(0x608)
11-26 10:12:40.126: D/MM_DEVICE(8389): Waiting for mm thread to come up
11-26 10:12:40.126: D/MM_DEVICE(8389): mm_device_thread starting
11-26 10:12:40.126: D/MM_DEVICE(8389): Waiting for mm thread to come up
11-26 10:12:40.136: D/HAWAII_EGL(8389): eglCreateContext() config: 18 context: 0x494b0bc0, VC context 1, Thread 8389
11-26 10:12:40.136: D/HAWAII_EGL(8389): Set SWAP INTERVAL 0
11-26 10:12:40.136: D/HAWAII_EGL(8389): eglCreateWindowSurface() surface: 0x494b0be0, VC surface: 1, Thread: 8389
11-26 10:12:40.136: D/HAWAII_EGL(8389): eglMakeCurrent(0x494b0bc0, 0x494b0be0, 0x494b0be0) Thread: 8389
11-26 10:12:40.136: D/OpenGLRenderer(8389): Enabling debug mode 0
11-26 10:12:40.156: D//SpiceService.java:134(8389): 10:12:40.165 main SpiceService instance created.
11-26 10:12:40.186: V//SpiceService.java:506(8389): 10:12:40.199 main Pending requests : 0
11-26 10:12:40.186: V//SpiceService.java:508(8389): 10:12:40.200 main Stop foreground
11-26 10:12:40.186: D/WritingBuddyImpl(8389): getCurrentWritingBuddyView()
11-26 10:12:40.306: D//SpiceServiceListenerNotifier.java:33(8389): 10:12:40.315 main Message Queue starting
11-26 10:12:40.306: D//SpiceManager.java:1088(8389): 10:12:40.316 main Bound to service : JacksonSpringAndroidSpiceService
11-26 10:12:40.306: D//SpiceManager.java:1252(8389): 10:12:40.318 SpiceManagerThread 0 Bound ok.
11-26 10:12:57.643: D//SpiceManager.java:489(8389): 10:12:57.648 main adding request to request queue
11-26 10:12:57.643: D//SpiceManager.java:286(8389): 10:12:57.649 SpiceManagerThread 0 Sending request to service : CachedSpiceRequest
11-26 10:12:57.663: D//RequestProcessor.java:63(8389): 10:12:57.669 SpiceManagerThread 0 Adding request to queue 1099810720: CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@41929530] size is 0
11-26 10:12:57.663: D//RequestProcessor.java:85(8389): 10:12:57.672 SpiceManagerThread 0 Adding entry for type class primoandroidmaven.myrobo.model.ShortURLResponse and cacheKey followers.short.
11-26 10:12:57.663: D//RequestProgressManager.java:61(8389): 10:12:57.674 SpiceManagerThread 0 Request was added to queue.
11-26 10:12:57.673: D//SpiceServiceListenerNotifier.java:146(8389): 10:12:57.676 SpiceManagerThread 0 Message queue is Handler (android.os.Handler) {41923a10}
11-26 10:12:57.673: D//RequestProgressManager.java:82(8389): 10:12:57.677 SpiceManagerThread 0 Sending progress PENDING
11-26 10:12:57.673: D//SpiceServiceListenerNotifier.java:146(8389): 10:12:57.679 SpiceManagerThread 0 Message queue is Handler (android.os.Handler) {41923a10}
11-26 10:12:57.693: D/ProgressBar(8389): updateDrawableBounds: left = 0
11-26 10:12:57.693: D/ProgressBar(8389): updateDrawableBounds: top = 0
11-26 10:12:57.693: D/ProgressBar(8389): updateDrawableBounds: right = 72
11-26 10:12:57.693: D/ProgressBar(8389): updateDrawableBounds: bottom = 72
11-26 10:12:57.703: D//SpiceServiceListenerNotifier.java:175(8389): 10:12:57.708 main Processing request added: CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@41929530]
11-26 10:12:57.703: V//DefaultRequestListenerNotifier.java:131(8389): 10:12:57.710 main Notifying 1 listeners of progress com.octo.android.robospice.request.listener.RequestProgress@41929b28
11-26 10:12:57.703: V//SpiceService.java:506(8389): 10:12:57.712 SpiceManagerThread 0 Pending requests : 1
11-26 10:12:57.703: V//SpiceService.java:508(8389): 10:12:57.713 SpiceManagerThread 0 Stop foreground
11-26 10:12:57.713: D//DefaultRequestRunner.java:83(8389): 10:12:57.724 Thread-2592 Processing request : CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@41929530]
11-26 10:12:57.723: D//DefaultRequestRunner.java:97(8389): 10:12:57.725 Thread-2592 Loading request from cache : CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@41929530]
11-26 10:12:57.723: D//RequestProgressManager.java:82(8389): 10:12:57.727 Thread-2592 Sending progress READING_FROM_CACHE
11-26 10:12:57.723: D//SpiceServiceListenerNotifier.java:146(8389): 10:12:57.728 Thread-2592 Message queue is Handler (android.os.Handler) {41923a10}
11-26 10:12:57.733: V//DefaultRequestListenerNotifier.java:131(8389): 10:12:57.738 main Notifying 1 listeners of progress com.octo.android.robospice.request.listener.RequestProgress@41948d00
11-26 10:12:57.733: D//DefaultRequestRunner.java:129(8389): 10:12:57.743 Thread-2592 Cache content not available or expired or disabled
11-26 10:12:57.743: D//DefaultRequestRunner.java:148(8389): 10:12:57.751 Thread-2592 Calling netwok request.
11-26 10:12:57.743: D//RequestProgressManager.java:82(8389): 10:12:57.752 Thread-2592 Sending progress LOADING_FROM_NETWORK
11-26 10:12:57.743: D//SpiceServiceListenerNotifier.java:146(8389): 10:12:57.753 Thread-2592 Message queue is Handler (android.os.Handler) {41923a10}
11-26 10:12:57.743: I/TEST(8389): CALLING
11-26 10:12:57.753: V//DefaultRequestListenerNotifier.java:131(8389): 10:12:57.756 main Notifying 1 listeners of progress com.octo.android.robospice.request.listener.RequestProgress@41955f38
11-26 10:12:57.834: D/dalvikvm(8389): GC_CONCURRENT freed 583K, 16% free 8868K/10484K, paused 2ms+3ms, total 25ms
11-26 10:12:58.624: D/dalvikvm(8389): GC_CONCURRENT freed 263K, 15% free 9010K/10484K, paused 17ms+3ms, total 48ms
11-26 10:12:58.915: I/TEST(8389): Called. Result: User disabled - -3
11-26 10:12:58.915: D//DefaultRequestRunner.java:151(8389): 10:12:58.923 Thread-2592 Network request call ended.
11-26 10:12:58.925: D//DefaultRequestRunner.java:171(8389): 10:12:58.926 Thread-2592 Start caching content...
11-26 10:12:58.925: D//RequestProgressManager.java:82(8389): 10:12:58.927 Thread-2592 Sending progress WRITING_TO_CACHE
11-26 10:12:58.925: D//SpiceServiceListenerNotifier.java:146(8389): 10:12:58.931 Thread-2592 Message queue is Handler (android.os.Handler) {41923a10}
11-26 10:12:58.935: V//DefaultRequestListenerNotifier.java:131(8389): 10:12:58.943 main Notifying 1 listeners of progress com.octo.android.robospice.request.listener.RequestProgress@4190bf60
11-26 10:12:58.945: D//RequestProgressManager.java:82(8389): 10:12:58.953 Thread-2592 Sending progress COMPLETE
11-26 10:12:58.945: D//SpiceServiceListenerNotifier.java:146(8389): 10:12:58.954 Thread-2592 Message queue is Handler (android.os.Handler) {41923a10}
11-26 10:12:58.955: D//SpiceServiceListenerNotifier.java:146(8389): 10:12:58.955 Thread-2592 Message queue is Handler (android.os.Handler) {41923a10}
11-26 10:12:58.955: V//RequestProgressManager.java:161(8389): 10:12:58.957 Thread-2592 Removing CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@41929530] size is 1
11-26 10:12:58.955: V//DefaultRequestListenerNotifier.java:131(8389): 10:12:58.958 main Notifying 1 listeners of progress com.octo.android.robospice.request.listener.RequestProgress@41936e28
11-26 10:12:58.955: V//DefaultRequestListenerNotifier.java:166(8389): 10:12:58.959 main Notifying 1 listeners of request success
11-26 10:12:58.955: V//DefaultRequestListenerNotifier.java:172(8389): 10:12:58.960 main Notifying ShortenRequestListener
11-26 10:12:58.965: D//RequestProgressManager.java:91(8389): 10:12:58.966 Thread-2592 Sending all request complete.
11-26 10:12:58.965: V//SpiceService.java:495(8389): 10:12:58.970 Thread-2592 Pending requests : 0
11-26 10:12:58.965: D//SpiceServiceListenerNotifier.java:146(8389): 10:12:58.971 Thread-2592 Message queue is Handler (android.os.Handler) {41923a10}
11-26 10:12:58.965: D//DefaultRequestRunner.java:295(8389): 10:12:58.972 Thread-2592 It tooks 1260 ms to process request CachedSpiceRequest [requestCacheKey=followers.short, cacheDuration=60000, spiceRequest=primoandroidmaven.myrobo.ShortenRequest@41929530].

Thank you

[kraghu]

@stephanenicolas i faced this problems offlate a lot. What can cause Robospice clear the request and not to return back any status ?

[axd1967]

I also sometimes run into requests that never get processed (and there is no device rotation or other funny Activity state stuff going on)

06-16 09:18:52.280 1852-1852/test D//SpiceManager.java:489: 09:18:52.295 main adding request to request queue
06-16 09:18:52.290 1852-7027/test D//SpiceManager.java:286: 09:18:52.302 SpiceManagerThread 1 Sending request to service : CachedSpiceRequest
06-16 09:18:52.290 1852-7027/test D//RequestProcessor.java:63: 09:18:52.303 SpiceManagerThread 1 Adding request to queue 1116400536: CachedSpiceRequest [requestCacheKey=test.rest.requests.GET_DirectionsRequest0, cacheDuration=-1, spiceRequest=test.rest.requests.GET_DirectionsRequest@42b71c50] size is 8
06-16 09:18:52.320 1852-7027/test D//RequestProcessor.java:90: 09:18:52.330 SpiceManagerThread 1 Request for type class test.rest.json.GET_Directions and cacheKey test.rest.requests.GET_DirectionsRequest0 already exists.
06-16 09:18:52.320 1852-7027/test D//RequestProgressManager.java:69: 09:18:52.331 SpiceManagerThread 1 Request was aggregated in queue.
06-16 09:18:52.320 1852-7027/test D//SpiceServiceListenerNotifier.java:146: 09:18:52.333 SpiceManagerThread 1 Message queue is Handler (android.os.Handler) {423f6648}
06-16 09:18:52.330 1852-7027/test D//RequestProgressManager.java:82: 09:18:52.335 SpiceManagerThread 1 Sending progress PENDING
06-16 09:18:52.330 1852-7027/test D//SpiceServiceListenerNotifier.java:146: 09:18:52.341 SpiceManagerThread 1 Message queue is Handler (android.os.Handler) {423f6648}
06-16 09:18:52.340 1852-7027/test V//SpiceService.java:506: 09:18:52.346 SpiceManagerThread 1 Pending requests : 16
06-16 09:18:52.340 1852-7027/test V//SpiceService.java:508: 09:18:52.348 SpiceManagerThread 1 Stop foreground
06-16 09:18:52.350 1852-1852/test D//SpiceServiceListenerNotifier.java:203: 09:18:52.357 main Processing request added: CachedSpiceRequest [requestCacheKey=test.rest.requests.GET_DirectionsRequest0, cacheDuration=-1, spiceRequest=test.rest.requests.GET_DirectionsRequest@42b71c50]
06-16 09:18:52.360 1852-1852/test V//DefaultRequestListenerNotifier.java:131: 09:18:52.373 main Notifying 1 listeners of progress com.octo.android.robospice.request.listener.RequestProgress@42aa1268

the "Pending request" counter just keeps going up.

    compile 'com.android.support:support-v4:23.3.0'
    compile 'com.android.support:appcompat-v7:23.3.0'
    compile 'com.octo.android.robospice:robospice-spring-android:1.4.14'
    compile 'com.google.http-client:google-http-client-jackson:1.15.0-rc'
    compile 'org.codehaus.jackson:jackson-mapper-asl:1.9.13'
    compile 'com.google.android.gms:play-services-base:8.4.0'
    compile 'com.google.android.gms:play-services-identity:8.4.0'
    compile 'com.google.android.gms:play-services-plus:8.4.0'
    compile 'com.google.android.gms:play-services-maps:8.4.0'
    compile 'com.google.android.gms:play-services-location:8.4.0'
    compile 'com.android.support:design:23.3.0'
    compile 'com.android.support:cardview-v7:23.3.0'
    compile 'com.android.support:gridlayout-v7:23.3.0'
    compile 'com.google.android.gms:play-services-analytics:8.4.0'
    compile 'de.psdev.licensesdialog:licensesdialog:1.8.0'
    compile 'com.google.android.gms:play-services-appindexing:8.4.0'

    compileSdkVersion 23
    buildToolsVersion "23.0.3"

    defaultConfig {
        minSdkVersion 11 // (3.0) various
        targetSdkVersion 21

but sometimes it happens that the request takes a very long time (several seconds) to complete, giving the impression that nothing is happening.