inconsistency issue with Objectify query result and Datastore viewer result?

Question

I'm coding a sample project based on TodoMVC angularjs (http://todomvc.com/) and with a backend api with Google App Engine Cloud Endpoint and I'm having some consistency result when getting the todos liste from App Engine Datastore.

Todo object are stored in the App Engine Datastore using objectify.

A Todo entity is coded as follow:

@Entity
public class Todo {

    @Id
    private Long id;
    private String title;
    private boolean completed;
    private Date lastEdit;

    @Index
    private Long userId;

    public Todo() {
    }

    public Todo(String title, boolean completed) {
        this.title = title;
        this.completed = completed;
    }

    public Todo(Long id, String title, boolean completed) {
        this.id = id;
        this.title = title;
        this.completed = completed;
    }

    public Long getId() {
        return id;
    }

    public void setId(Long id) {
        this.id = id;
    }

    public String getTitle() {
        return title;
    }

    public void setTitle(String title) {
        this.title = title;
    }

    public boolean isCompleted() {
        return completed;
    }

    public void setCompleted(boolean completed) {
        this.completed = completed;
    }

    public Long getUserId() {
        return userId;
    }

    public void setUserId(Long userId) {
        this.userId = userId;
    }

    public Date getLastEdit() {
        return lastEdit;
    }

    public void setLastEdit(Date lastEdit) {
        this.lastEdit = lastEdit;
    }

    @Override
    public String toString() {
        return "Todo{" +
                "id=" + id +
                ", title='" + title + '\'' +
                ", completed=" + completed +
                ", lastEdit=" + lastEdit +
                ", userId='" + userId + '\'' +
                '}';
    }
}

Saving a Todo in Datastore is done as follow:

@ApiMethod(name = "create", httpMethod =  ApiMethod.HttpMethod.POST)
public Todo create(User user, Todo todo) {
    logger.info("creating todo : " + todo.toString());

    todo.setUserId(new Long(user.getUserId()));
    todo.setLastEdit(new Date());
    ofy().save().entity(todo).now();

    return todo;
}



@ApiMethod(name = "list", httpMethod =  ApiMethod.HttpMethod.GET)
public Collection<Todo> getTodos(User user) {
    logger.info("user:" + user);

    List<Todo> todos = null;

    if (user != null) {
        todos = ofy().consistency(ReadPolicy.Consistency.STRONG).load().type(Todo.class).filter("userId", new Long(user.getUserId())).list();
    }

    logger.info("todos:" + todos);

    return todos;
}

Let say I have 4 todos in my list and I set all of them to completed (completed=true). I check their state in the Datastore viewer:

Then if I request the list a few seconds after I will have the strange consistency issue :

2014-03-08 13:08:43.326
fr.xebia.gae.todo.api.TodoEndpointV2 getTodos: todos:[
Todo{id=5639274879778816, title='vélo', completed=false, lastEdit=Fri Mar 07 23:36:08 UTC 2014, userId='104955400895435072612'}, 
Todo{id=5676830073815040, title='train', completed=true, lastEdit=Sat Mar 08 12:08:30 UTC 2014, userId='104955400895435072612'}, 
Todo{id=5717271485874176, title='avion', completed=false, lastEdit=Fri Mar 07 23:36:09 UTC 2014, userId='104955400895435072612'}, 
Todo{id=5757334940811264, title='voiture', completed=true, lastEdit=Sat Mar 08 12:08:32 UTC 2014, userId='104955400895435072612'}]

as you can see the completed value is not set to true for all the todos and their lastEdit date is even not updated

new request 2 minutes later :

2014-03-08 13:10:20.612
fr.xebia.gae.todo.api.TodoEndpointV2 getTodos: todos:[
Todo{id=5639274879778816, title='vélo', completed=false, lastEdit=Fri Mar 07 23:36:08 UTC 2014, userId='104955400895435072612'}, 
Todo{id=5676830073815040, title='train', completed=true, lastEdit=Sat Mar 08 12:08:30 UTC 2014, userId='104955400895435072612'}, 
Todo{id=5717271485874176, title='avion', completed=false, lastEdit=Fri Mar 07 23:36:09 UTC 2014, userId='104955400895435072612'}, 
Todo{id=5757334940811264, title='voiture', completed=true, lastEdit=Sat Mar 08 12:08:32 UTC 2014, userId='104955400895435072612'}]

and new request 17 minutes later, still not the good values ...

2014-03-08 13:27:07.918
fr.xebia.gae.todo.api.TodoEndpointV2 getTodos: todos:[Todo{id=5639274879778816, title='vélo', completed=false, lastEdit=Fri Mar 07 23:36:08 UTC 2014, userId='104955400895435072612'}, 
Todo{id=5676830073815040, title='train', completed=true, lastEdit=Sat Mar 08 12:08:30 UTC 2014, userId='104955400895435072612'}, 
Todo{id=5717271485874176, title='avion', completed=false, lastEdit=Fri Mar 07 23:36:09 UTC 2014, userId='104955400895435072612'}, 
Todo{id=5757334940811264, title='voiture', completed=true, lastEdit=Sat Mar 08 12:08:32 UTC 2014, userId='104955400895435072612'}]

Does someone knows why their is such differences between what is queried with Objectify and with what is viewable with the GAE Datastore viewer backoffice ? Is is consistency issue ? but if so why the datastore viewer doesn't have the same issue ? Am I misusing objectify when querying (event if I set ofy().consistency(ReadPolicy.Consistency.STRONG) when running filter) ?

Answer 1

I didn't read well the objectify setup and I missed the part where it tells that one should add the following to the web.xml

<filter>
     <filter-name>ObjectifyFilter</filter-name>
     <filter-class>com.googlecode.objectify.ObjectifyFilter</filter-class>
</filter>
<filter-mapping>
     <filter-name>ObjectifyFilter</filter-name>
     <url-pattern>/*</url-pattern> 
</filter-mapping>

Answer 2

You probably have objectify caching enabled. Objectify has two levels of cache (instance and memcache). In any case because of eventual consistency you can always get different results until enough time passes.