5

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:

datastore viewer showing that the completed value is set to true for all todo items

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) ?

Jean-Baptiste
  • 387
  • 3
  • 11
  • 1
    I don't believe `ReadPolicy.Consistency.STRON`G will have any impact on the underlying datastores eventual consistency. To prove this, fetch one of the entities that seems out of date by Key rather than a query and see of the entity is in fact out of date. Fetching by key or using an ancestor in the key will fetch the true state of an entity as far as the datastore is concerned. – Tim Hoffman Mar 09 '14 at 00:18

2 Answers2

3

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>
Jean-Baptiste
  • 387
  • 3
  • 11
1

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.

Zig Mandel
  • 19,571
  • 5
  • 26
  • 36
  • 1
    Click on Flush Memcache in a Datastore viewer, and then run your query again. – Andrei Volgin Mar 08 '14 at 15:07
  • nop even so after flushing memcache in datastore viewer, it still retrieves only one part on the updated todo entities :-/ – Jean-Baptiste Mar 08 '14 at 15:38
  • you are missing the other cache (instance). To force-flush it you need to kill the instance (by waiting 15min with no calls, or by changing the instance size so next call will generate a new instance. – Zig Mandel Mar 08 '14 at 17:42
  • Cache in objectify is write-through, so it should not be an issue here. IMO, what OP is experiencing is eventual consistency. – Peter Knego Mar 08 '14 at 22:52
  • but 17 minutes would be very unusual if it was eventual consistency. chache in objectify is write-through only for the memcache part. If you have more than one instance, one will not see the other's writes because of objetify (lets say a frontend and a taskqueue). – Zig Mandel Mar 09 '14 at 01:33