Difference in sequence of query generated in Django and Postgres for select_for_update

I'm facing a strange situation, where sequence of query logged in Django and Postgres is different when using select_for_update() inside transaction.atomic() block.

Basically I've a ModelForm where I'm validating the cleaned_data against the database, for duplicate request. And then in create view's form_valid() method, I'm saving the instance. To have both the operation inside same transaction, I'm overriding post() method, and wrapping those two method calls inside transaction.atomic().

Here's the code for whatever I said above:

# Form
class MenuForm(forms.ModelForm):
    def __init__(self, *args, **kwargs):
        user_id = kwargs.pop('user_id', None)
        super(MenuForm, self).__init__(*args, **kwargs)

    def clean(self):
        cleaned_data = super(MenuForm, self).clean()
        dish_name = cleaned_data.get('dish_name')
        menus = Menu.objects.select_for_update().filter(user_id=self.user_id)

        for menu in menus:
            if menu.dish_name == dish_name:
                self.add_error('dish_name', 'Dish already exists')
                return cleaned_data
        return cleaned_data

# CreateView
class MenuCreateView(CreateView):
    form_class = MenuForm

    def get_form_kwargs(self):
        kwargs = super(MenuCreateView, self).get_form_kwargs()
        kwargs.update({'user_id': self.request.session.get('user_id')})
        return kwargs

    def form_valid(self, form):
        user = User.objects.get(id=self.request.session.get('user_id'))
        form.instance.user = user
        return super(MenuCreateView, self).form_valid(form)

    def post(self, request, *args, **kwargs):
        form = self.get_form()

        with transaction.atomic():
            if form.is_valid():
                return self.form_valid(form)
            else:
                return self.form_invalid(form)

Now suppose I fire two request at the same time, to create a menu with same dish. I expect the second request to fail. But, both of them are passing. It looks like, the second transaction is not seeing the changes done in previous transaction. Because of which, the total menus remain the same in both the transaction that is returned by select_for_update().

Given that Postgres default Isolation level is READ COMMITTED, I expect the changes to be visible. So, I tried logging the queries to see that COMMIT; is fired at right time. Here's the query log by django and in postgres:

Django Log:

SELECT "menu"."id", "menu"."dish_id", "menu"."dish_name" FROM "menu" WHERE ("menu"."dish_name" = "Test Dish") FOR UPDATE; args=("Test Dish")    
INSERT INTO "menu" ("dish_id", "dish_name") VALUES (2, "Test Dish") RETURNING "menu"."id"; args=(2, "Test Dish")
SELECT "menu"."id", "menu"."dish_id", "menu"."dish_name" FROM "menu" WHERE ("menu"."dish_name" = "Test Dish") FOR UPDATE; args=("Test Dish")
INSERT INTO "menu" ("dish_id", "dish_name") VALUES (2, "Test Dish") RETURNING "menu"."id"; args=(2, "Test Dish")

Postgres Log:

<2016-03-18 17:55:46.176 IST  0  2/31  56ebf3ca.aac0>LOG:  statement: SHOW default_transaction_isolation
<2016-03-18 17:55:46.177 IST  0  2/32  56ebf3ca.aac0>LOG:  statement: SET TIME ZONE 'UTC'
<2016-03-18 17:55:46.178 IST  0  2/33  56ebf3ca.aac0>LOG:  statement: SELECT t.oid, typarray
    FROM pg_type t JOIN pg_namespace ns
        ON typnamespace = ns.oid
    WHERE typname = 'hstore';

<2016-03-18 17:55:46.182 IST  0  2/34  56ebf3ca.aac0>LOG:  statement: BEGIN
<2016-03-18 17:55:46.301 IST  0  3/2  56ebf3ca.aac1>LOG:  statement: SHOW default_transaction_isolation
<2016-03-18 17:55:46.302 IST  0  3/3  56ebf3ca.aac1>LOG:  statement: SET TIME ZONE 'UTC'
<2016-03-18 17:55:46.302 IST  0  3/4  56ebf3ca.aac1>LOG:  statement: SELECT t.oid, typarray
    FROM pg_type t JOIN pg_namespace ns
        ON typnamespace = ns.oid
    WHERE typname = 'hstore';

<2016-03-18 17:55:46.312 IST  0  3/5  56ebf3ca.aac1>LOG:  statement: BEGIN
<2016-03-18 17:55:46.963 IST  0  3/5  56ebf3ca.aac1>LOG:  statement: SELECT "menu"."id", "menu"."dish_id", "menu"."dish_name" FROM "menu" 
WHERE ("menu"."dish_name" = "Test Dish") FOR UPDATE
<2016-03-18 17:55:46.964 IST  0  2/34  56ebf3ca.aac0>LOG:  statement: SELECT "menu"."id", "menu"."dish_id", "menu"."dish_name" FROM "menu" 
WHERE ("menu"."dish_name" = "Test Dish") FOR UPDATE
<2016-03-18 17:55:47.040 IST  23712  3/5  56ebf3ca.aac1>LOG:  statement: INSERT INTO "menu" ("dish_id", "dish_name") VALUES (2, "Test Dish")RETURNING "menu"."id"
<2016-03-18 17:55:47.061 IST  23712  3/5  56ebf3ca.aac1>LOG:  statement: COMMIT
<2016-03-18 17:55:47.229 IST  23713  2/34  56ebf3ca.aac0>LOG:  statement: INSERT INTO "menu" ("dish_id", "dish_name") VALUES (2, "Test Dish")RETURNING "menu"."id"
<2016-03-18 17:55:47.231 IST  23713  2/34  56ebf3ca.aac0>LOG:  statement: COMMIT

Postgres.conf:

max_connections = 100
log_destination = 'stderr'
logging_collector = on
log_directory = 'pg_log'
log_line_prefix = '<%m  %x  %v  %c>'
log_statement = 'all'

As you can see, the order of SELECT and INSERT queries in not the same in both the logs. I'm unable to understand why this would happen. Also, if you notice, the session_id for the SELECT queries in Postgres log is different. Could that explain something here?

And if this is expected behaviour, how could I solve the core issue here? Avoid concurrent INSERT queries, based on existing record.

UPDATE:

I didn't mention that the actual logic to ignore duplicate menu is not just based on dish name. The one above is simplified example.

Considering menu model as:

class Menu:
    user_id = models.IntegerField()
    dish = models.ForeignKey(Dish)
    order_start_time = models.DateTimeField()
    order_end_time = models.DateTimeField()

The actual logic goes like this:

• Fetch all menu with the dish_name from db.
• Check the order_start_time and order_end_time for all the those menu, and see if any of them overlaps with the order_start_time and order_end_time for the new menu. If conflict found, avoid addition.

So, we can add two menu for dish - d1, having order window - [9am-10am] and [2pm-3pm].