Unexpected order of WebSocket messages

[iRevive]

trafficstars

Hi all,

I'm implementing a client for Jupyter WebSocket protocol using Netty. But for an unexpected reason, the application receives responses in non-chronological order.

According to the documentation (https://jupyter-client.readthedocs.io/en/latest/messaging.html), Idle status should guarantee that all messages related to the request were sent to the client:

The client sends an < action >_request message (such as execute_request) on its shell (DEALER) socket. The kernel receives that request and immediately publishes a status: busy message on IOPub. The kernel then processes the request and sends the appropriate < action >_reply message, such as execute_reply. After processing the request and publishing associated IOPub messages, if any, the kernel publishes a status: idle message. This idle status message indicates that IOPub messages associated with a given request have all been received.

But according to the logs, the system receives kernel_info_reply after Idle status.

2019-08-05 14:38:22,795 [INFO] nioEventLoopGroup-2-1 c.a.o.u.w.WebSocketClientHandler - Frame {"header": {"msg_id": "12c89888-6755-4daf-92c2-fa2476bbf890", "username": "jovyan", "session": "49158048-c6c4-4a74-9208-2be97170feb5", "msg_type": "status", "version": "5.0", "date": "2019-08-05T11:38:22.808627Z"}, "msg_id": "12c89888-6755-4daf-92c2-fa2476bbf890", "msg_type": "status", "parent_header": {"msg_id": "8989dc4d-ba07-460c-a0e3-73f4b5dd78cb", "username": "", "session": "", "msg_type": "kernel_info_request", "version": "5.0"}, "metadata": {"timestamp": 1565005102797}, "content": {"execution_state": "busy"}, "buffers": [], "channel": "iopub"}
2019-08-05 14:38:22,802 [INFO] nioEventLoopGroup-2-1 c.a.o.u.w.WebSocketClientHandler - Frame {"header": {"msg_id": "7a3240ec-5702-4a57-92ab-0647f47e669a", "username": "jovyan", "session": "49158048-c6c4-4a74-9208-2be97170feb5", "msg_type": "status", "version": "5.0", "date": "2019-08-05T11:38:22.818220Z"}, "msg_id": "7a3240ec-5702-4a57-92ab-0647f47e669a", "msg_type": "status", "parent_header": {"msg_id": "8989dc4d-ba07-460c-a0e3-73f4b5dd78cb", "username": "", "session": "", "msg_type": "kernel_info_request", "version": "5.0"}, "metadata": {"timestamp": 1565005102805}, "content": {"execution_state": "idle"}, "buffers": [], "channel": "iopub"}
2019-08-05 14:38:22,805 [INFO] nioEventLoopGroup-2-1 c.a.o.u.w.WebSocketClientHandler - Frame {"header": {"msg_id": "4452e1d0-3cc2-4dd2-a127-c0c1465fe18a", "username": "", "session": "29c22121-1035-423e-883a-eb4ff1012299", "msg_type": "kernel_info_reply", "version": "5.0", "date": "2019-08-05T11:38:22.819727Z"}, "msg_id": "4452e1d0-3cc2-4dd2-a127-c0c1465fe18a", "msg_type": "kernel_info_reply", "parent_header": {"msg_id": "8989dc4d-ba07-460c-a0e3-73f4b5dd78cb", "username": "", "session": "", "msg_type": "kernel_info_request", "version": "5.0"}, "metadata": {"timestamp": 1565005102804}, "content": {"protocol_version": "5.0", "implementation": "spark", "implementation_version": "0.3.0-incubating", "language_info": {"name": "scala", "version": "2.11.12", "file_extension": ".scala", "pygments_lexer": "scala", "mimetype": "text/x-scala", "codemirror_mode": "text/x-scala"}, "banner": "Apache Toree"}, "buffers": [], "channel": "shell"}

The most interesting thing is that according to field metadata.timestamp event kernel_info_reply was created before Idle. But according to the field header.date it wasn't.

UI client sometimes receives unordered messages too:

[tirumalavasu-modak]

Hi all,

I'm implementing a client for Jupyter WebSocket protocol using Netty. But for an unexpected reason, the application receives responses in non-chronological order.

According to the documentation (https://jupyter-client.readthedocs.io/en/latest/messaging.html), Idle status should guarantee that all messages related to the request were sent to the client:

The client sends an < action >_request message (such as execute_request) on its shell (DEALER) socket. The kernel receives that request and immediately publishes a status: busy message on IOPub. The kernel then processes the request and sends the appropriate < action >_reply message, such as execute_reply. After processing the request and publishing associated IOPub messages, if any, the kernel publishes a status: idle message. This idle status message indicates that IOPub messages associated with a given request have all been received.

But according to the logs, the system receives kernel_info_reply after Idle status.

2019-08-05 14:38:22,795 [INFO] nioEventLoopGroup-2-1 c.a.o.u.w.WebSocketClientHandler - Frame {"header": {"msg_id": "12c89888-6755-4daf-92c2-fa2476bbf890", "username": "jovyan", "session": "49158048-c6c4-4a74-9208-2be97170feb5", "msg_type": "status", "version": "5.0", "date": "2019-08-05T11:38:22.808627Z"}, "msg_id": "12c89888-6755-4daf-92c2-fa2476bbf890", "msg_type": "status", "parent_header": {"msg_id": "8989dc4d-ba07-460c-a0e3-73f4b5dd78cb", "username": "", "session": "", "msg_type": "kernel_info_request", "version": "5.0"}, "metadata": {"timestamp": 1565005102797}, "content": {"execution_state": "busy"}, "buffers": [], "channel": "iopub"}
2019-08-05 14:38:22,802 [INFO] nioEventLoopGroup-2-1 c.a.o.u.w.WebSocketClientHandler - Frame {"header": {"msg_id": "7a3240ec-5702-4a57-92ab-0647f47e669a", "username": "jovyan", "session": "49158048-c6c4-4a74-9208-2be97170feb5", "msg_type": "status", "version": "5.0", "date": "2019-08-05T11:38:22.818220Z"}, "msg_id": "7a3240ec-5702-4a57-92ab-0647f47e669a", "msg_type": "status", "parent_header": {"msg_id": "8989dc4d-ba07-460c-a0e3-73f4b5dd78cb", "username": "", "session": "", "msg_type": "kernel_info_request", "version": "5.0"}, "metadata": {"timestamp": 1565005102805}, "content": {"execution_state": "idle"}, "buffers": [], "channel": "iopub"}
2019-08-05 14:38:22,805 [INFO] nioEventLoopGroup-2-1 c.a.o.u.w.WebSocketClientHandler - Frame {"header": {"msg_id": "4452e1d0-3cc2-4dd2-a127-c0c1465fe18a", "username": "", "session": "29c22121-1035-423e-883a-eb4ff1012299", "msg_type": "kernel_info_reply", "version": "5.0", "date": "2019-08-05T11:38:22.819727Z"}, "msg_id": "4452e1d0-3cc2-4dd2-a127-c0c1465fe18a", "msg_type": "kernel_info_reply", "parent_header": {"msg_id": "8989dc4d-ba07-460c-a0e3-73f4b5dd78cb", "username": "", "session": "", "msg_type": "kernel_info_request", "version": "5.0"}, "metadata": {"timestamp": 1565005102804}, "content": {"protocol_version": "5.0", "implementation": "spark", "implementation_version": "0.3.0-incubating", "language_info": {"name": "scala", "version": "2.11.12", "file_extension": ".scala", "pygments_lexer": "scala", "mimetype": "text/x-scala", "codemirror_mode": "text/x-scala"}, "banner": "Apache Toree"}, "buffers": [], "channel": "shell"}

The most interesting thing is that according to field metadata.timestamp event kernel_info_reply was created before Idle. But according to the field header.date it wasn't.

UI client sometimes receives unordered messages too:

@iRevive Any luck? I am getting same issue.