[ISILONQE-1417] Pike TimeoutError should be actionable #92

isi-mfurer · 2020-10-05T23:11:26Z

Add context to TimeoutError by optionally allowing it to be raised with_future specified. If the Future has a .request attribute, then it will be included in the TimeoutError string representation.

Callers may catch the TimeoutError and further inspect the .future or even wait for it again.

Update pike's use of Future to include relevant "request" context information where possible.

Existing raisers of pike.model.TimeoutError outside of this package are unaffected as the signature and behavior of TimeoutError are backward compatible with the previous implementation.

Testing Done

No explicit test cases are added for this change. Some scenarios were manually generated as an example and to check all code paths.

Connect Timeout

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/git/pike/pike/test/__init__.py", line 286, in __call__
    self.connect()
  File "/git/pike/pike/test/__init__.py", line 216, in connect
    self.conn = self.client.connect(server=self.server, port=self.port).negotiate()
  File "/git/pike/pike/model.py", line 419, in connect
    return self.connect_submit(server, port).result()
  File "/git/pike/pike/model.py", line 269, in result
    self.wait(timeout)
  File "/git/pike/pike/model.py", line 239, in wait
    raise TimeoutError.with_future(self, 'Timed out after %s seconds' % timeout)
pike.model.TimeoutError: Timed out after 30 seconds
Request: ('10.7.183.206', 445)

Session Setup Timeout:

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/git/pike/pike/test/__init__.py", line 248, in session_setup
    self.chan = self.conn.session_setup(self.creds, resume=self.resume)
  File "/git/pike/pike/model.py", line 1235, in session_setup
    return session_context.submit().result()
  File "/git/pike/pike/model.py", line 280, in result
    self.wait(timeout)
  File "/git/pike/pike/model.py", line 248, in wait
    raise TimeoutError.with_future(self, 'Timed out after %s seconds' % timeout)
pike.model.TimeoutError: Timed out after 0.1 seconds
Request: Smb2
  credit_charge: 1
  channel_sequence: 0
  command: SMB2_SESSION_SETUP
  credit_request: 10
  flags: SMB2_FLAGS_NONE
  next_command: 0
  message_id: 1
  session_id: 0
  tree_id: 0
  signature: 0x00000000000000000000000000000000
  buf: 0xfe534d42400001000000000001000a0000000000000000000100000000000000fffe0000000000000000000000000000000000000000000000000000000000001900000100000000000000005800300000000000000000004e544c4d5353500001000000371208e00800080028000000000000003000000000000000000000004e004f004e004500
  SessionSetupRequest
    flags: 0
    security_mode: SMB2_NEGOTIATE_SIGNING_ENABLED
    capabilities: 0
    channel: 0
    previous_session_id: 0
    security_buffer: 0x4e544c4d5353500001000000371208e00800080028000000000000003000000000000000000000004e004f004e004500
    security_buffer_offset: 88
    security_buffer_length: 48
Smb2
  credit_charge: 1
  channel_sequence: 0
  command: SMB2_SESSION_SETUP
  credit_request: 10
  flags: SMB2_FLAGS_NONE
  next_command: 0
  message_id: 2
  session_id: 87152583017234869
  tree_id: 0
  signature: 0x00000000000000000000000000000000
  SessionSetupRequest
    flags: 0
    security_mode: SMB2_NEGOTIATE_SIGNING_ENABLED
    capabilities: 0
    channel: 0
    previous_session_id: 0
    security_buffer: 0x4e544c4d53535000030000001800180048000000a800a80060000000080008000801000008000800100100001200120018010000100010002a010000350289e00000000000000000a23669929e22cf9a2722b3f52301d0a24b4e77a8013e8836b783bb575e3ba0ec39ad2d9d0fe2cf340101000000000000809f80564f9bd6014b4e77a8013e88360000000002001a004d0046005300450041004e004f0044004500340032002d00310001001a004d0046005300450041004e004f0044004500340032002d00310004001a006d0066007300650061006e006f0064006500340032002d00310003001a006d0066007300650061006e006f0064006500340032002d003100000000004e004f004e00450072006f006f0074006d00660075007200650072002d0077007300eedc13d5257b261423aafee075ce3326
    security_buffer_offset: 88
    security_buffer_length: 314

Tree Timeout

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/git/pike/pike/test/__init__.py", line 267, in tree_connect
    self.tree = self.chan.tree_connect(self.share)
  File "/git/pike/pike/model.py", line 1372, in tree_connect
    path)).result()
  File "/git/pike/pike/model.py", line 280, in result
    self.wait(timeout)
  File "/git/pike/pike/model.py", line 248, in wait
    raise TimeoutError.with_future(self, 'Timed out after %s seconds' % timeout)
pike.model.TimeoutError: Timed out after 0.001 seconds
Request: Smb2
  credit_charge: 1
  channel_sequence: 0
  command: SMB2_TREE_CONNECT
  credit_request: 10
  flags: SMB2_FLAGS_SIGNED
  next_command: 0
  message_id: 5
  session_id: 87152583017234872
  tree_id: 0
  signature: 0xeaa9955cb6738f07bb8a8961d3ba73bf
  TreeConnectRequest
    flags: 0
    path_offset: 72
    path_length: 36
    path: \\10.7.183.208\ifs

Lease Timeout

*** pike.model.TimeoutError: Timed out after 0.1 seconds
Request: LeaseBreak
0x61e2400411d4d18213475283f3827820

Oplock Timeout

E               pike.model.TimeoutError: Timed out after 0.1 seconds
E               Request: OplockBreak
E               (70026, 1)

Create Timeout

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/git/pike/pike/model.py", line 280, in result
    self.wait(timeout)
  File "/git/pike/pike/model.py", line 248, in wait
    raise TimeoutError.with_future(self, 'Timed out after %s seconds' % timeout)
pike.model.TimeoutError: Timed out after 0.01 seconds
Request: Smb2
  credit_charge: 1
  channel_sequence: 0
  command: SMB2_CREATE
  credit_request: 10
  flags: SMB2_FLAGS_NONE
  next_command: 0
  message_id: 4
  session_id: 87152583017234891
  tree_id: 1
  signature: 0x00000000000000000000000000000000
  CreateRequest
    security_flags: 0
    requested_oplock_level: SMB2_OPLOCK_LEVEL_NONE
    impersonation_level: 0
    smb_create_flags: 0
    reserved: 0
    desired_access: GENERIC_WRITE | GENERIC_READ
    file_attributes: FILE_ATTRIBUTE_NORMAL
    share_access: 0
    create_disposition: FILE_OPEN_IF
    create_options: 0
    name: foo
    name_offset: 120
    name_length: 6
    create_contexts_offset: 0
    create_contexts_length: 0
    open_future: <pike.model.Future object at 0x7efe02048860>
    finish: <function Channel.create_request.<locals>.finish at 0x7efe057cb598>

Write Timeout

(This one could actually contain up to 1Mb of data, yikes!)

Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
  File "/git/pike/pike/model.py", line 1818, in write
    flags).parent.parent)
  File "/git/pike/pike/model.py", line 967, in transceive
    return [f.result() for f in self.submit(req)]
  File "/git/pike/pike/model.py", line 967, in <listcomp>
    return [f.result() for f in self.submit(req)]
  File "/git/pike/pike/model.py", line 280, in result
    self.wait(timeout)
  File "/git/pike/pike/model.py", line 248, in wait
    raise TimeoutError.with_future(self, 'Timed out after %s seconds' % timeout)
pike.model.TimeoutError: Timed out after 0.01 seconds
Request: Smb2
  credit_charge: 1
  channel_sequence: 0
  command: SMB2_WRITE
  credit_request: 10
  flags: SMB2_FLAGS_NONE
  next_command: 0
  message_id: 8
  session_id: 87152583017234891
  tree_id: 1
  signature: 0x00000000000000000000000000000000
  WriteRequest
    offset: 0
    file_id: (70029, 2)
    remaining_bytes: 0
    flags: 0
    buffer: b'foobarbaz'
    data_offset: 112
    length: 9
    channel: 0
    write_channel_info_offset: 0
    write_channel_info_length: 0

On a Future that has received an interim response

E               pike.model.TimeoutError: Timed out after 10 seconds
E               Request: Smb2
E                 credit_charge: 1
E                 channel_sequence: 0
E                 command: SMB2_CREATE
E                 credit_request: 10
E                 flags: SMB2_FLAGS_NONE
E                 next_command: 0
E                 message_id: 6
E                 session_id: 87152583017234907
E                 tree_id: 1
E                 signature: 0x00000000000000000000000000000000
E                 CreateRequest
E                   security_flags: 0
E                   requested_oplock_level: SMB2_OPLOCK_LEVEL_LEASE
E                   impersonation_level: 0
E                   smb_create_flags: 0
E                   reserved: 0
E                   desired_access: GENERIC_WRITE | GENERIC_READ
E                   file_attributes: FILE_ATTRIBUTE_NORMAL
E                   share_access: FILE_SHARE_READ | FILE_SHARE_WRITE | FILE_SHARE_DELETE
E                   create_disposition: FILE_OPEN_IF
E                   create_options: 0
E                   name: lease.txt
E                   name_offset: 120
E                   name_length: 18
E                   create_contexts_offset: 0
E                   create_contexts_length: 0
E                   open_future: <pike.model.Future object at 0x7f48d2f87940>
E                   finish: <function Channel.create_request.<locals>.finish at 0x7f48d31b7d08>
E                   LeaseRequest
E                     lease_key: 0x2f84b9676a9bc7036cbbf5ada307896d
E                     lease_state: SMB2_LEASE_READ_CACHING | SMB2_LEASE_HANDLE_CACHING | SMB2_LEASE_WRITE_CACHING
E               Interim: Smb2
E                 credit_charge: 1
E                 status: STATUS_PENDING
E                 command: SMB2_CREATE
E                 credit_response: 0
E                 flags: SMB2_FLAGS_SERVER_TO_REDIR | SMB2_FLAGS_ASYNC_COMMAND
E                 next_command: 0
E                 message_id: 6
E                 async_id: 1
E                 session_id: 87152583017234907
E                 signature: 0x00000000000000000000000000000000
E                 ErrorResponse
E                   byte_count: 0
E                   error_context_count: 0

Still works without a future passed:

>>> raise pike.model.TimeoutError("This timeout doesn't have a future")
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
pike.model.TimeoutError: This timeout doesn't have a future

Make pike.core.Frame._value_str a staticmethod which can be used in another module to format values the same way as the Frame pretty printer.

Allow a running program to overwrite pike.model.default_timeout for Future timeout. (as written before, the default_timeout gets baked into the function signature at module import time and changing the default_timeout variable has no effect)

TimeoutError.with_future is a factory classmethod that returns a TimeoutError with the .future attribute set. TimeoutError.__str__ formats the exception with the Future.request and Future.interim_response (if they exist).

Include a reference to the Future that timed out for better post-mortem analysis.

Pass a request value to all Futures to provide contextual information if the Future times out. These are not necessarily core.Frame objects.

isi-adas

Great. Looks like from now we will have a detailed req/resp capture trace of where and when it timed out.

jtmoon79 · 2020-10-06T02:02:28Z

Review: I like this PR! 👍

jtmoon79

LGTM ... tho futures feel like trying to think of 7+1 things at once. (asynch code in a static code review is hard).
I'm mostly sure this statement does not need an update https://github.com/emc-isilon/pike/pull/92/files#diff-ec153015e2fc91150abad84525c67330R950

isi-mfurer · 2020-10-06T02:15:12Z

I'm mostly sure this statement does not need an update

hmm, that link doesn't point to a line for me. what line are you referring to? i may have missed a spot

jtmoon79 · 2020-10-06T02:20:22Z

I'm mostly sure this statement does not need an update

hmm, that link doesn't point to a line for me. what line are you referring to? i may have missed a spot

https://github.com/emc-isilon/pike/blob/master/pike/model.py#L915

isi-mfurer · 2020-10-06T02:23:22Z

ah okay, so that statement doesn't need to be updated... but it might benefit readability to update it as well as 912 to pass request=smb_req by kwarg

add Masen Furer to authors comment

Improve readability by passing smb_req by kwarg when creating new Future instances.

isi-mfurer · 2020-10-06T20:04:15Z

@jtmoon79 updated author information and passing smb_req by kwarg

3.9 was released yesterday and deadsnakes wont use the -dev version anymore

isi-mfurer · 2020-10-06T20:09:09Z

had to bring in python 3.9-release for the CI workflow, since that was released after this PR was opened and 3.9-dev no longer works

isi-mfurer added 5 commits October 5, 2020 15:49

pike.core: convert _value_str to static

004b569

Make pike.core.Frame._value_str a staticmethod which can be used in another module to format values the same way as the Frame pretty printer.

pike.model: extend TimeoutError

07d6ff3

TimeoutError.with_future is a factory classmethod that returns a TimeoutError with the .future attribute set. TimeoutError.__str__ formats the exception with the Future.request and Future.interim_response (if they exist).

pike.model: Future raises TimeoutError.with_future

91f12da

Include a reference to the Future that timed out for better post-mortem analysis.

pike.model: provide requests for all Futures

1ffdfc4

Pass a request value to all Futures to provide contextual information if the Future times out. These are not necessarily core.Frame objects.

isi-adas approved these changes Oct 5, 2020

View reviewed changes

isi-adas requested a review from jtmoon79 October 6, 2020 02:04

jtmoon79 approved these changes Oct 6, 2020

View reviewed changes

isi-mfurer added 3 commits October 6, 2020 13:00

pike.core: update authors information

1a86deb

add Masen Furer to authors comment

pike.model: update authors information

07f1079

add Masen Furer to authors comment

pike.model: pass smb_req by kwarg

a40b24e

Improve readability by passing smb_req by kwarg when creating new Future instances.

workflows/test_samba.yml: use python 3.9 release

42ca6f8

3.9 was released yesterday and deadsnakes wont use the -dev version anymore

isi-mfurer merged commit 5ac01f0 into emc-isilon:master Oct 6, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[ISILONQE-1417] Pike TimeoutError should be actionable #92

[ISILONQE-1417] Pike TimeoutError should be actionable #92

isi-mfurer commented Oct 5, 2020

isi-adas left a comment •

edited

jtmoon79 commented Oct 6, 2020 •

edited

jtmoon79 left a comment

isi-mfurer commented Oct 6, 2020

jtmoon79 commented Oct 6, 2020

isi-mfurer commented Oct 6, 2020

isi-mfurer commented Oct 6, 2020

isi-mfurer commented Oct 6, 2020

[ISILONQE-1417] Pike TimeoutError should be actionable #92

[ISILONQE-1417] Pike TimeoutError should be actionable #92

Conversation

isi-mfurer commented Oct 5, 2020

Testing Done

Connect Timeout

Session Setup Timeout:

Tree Timeout

Lease Timeout

Oplock Timeout

Create Timeout

Write Timeout

On a Future that has received an interim response

Still works without a future passed:

isi-adas left a comment • edited

Choose a reason for hiding this comment

jtmoon79 commented Oct 6, 2020 • edited

jtmoon79 left a comment

Choose a reason for hiding this comment

isi-mfurer commented Oct 6, 2020

jtmoon79 commented Oct 6, 2020

isi-mfurer commented Oct 6, 2020

isi-mfurer commented Oct 6, 2020

isi-mfurer commented Oct 6, 2020

isi-adas left a comment •

edited

jtmoon79 commented Oct 6, 2020 •

edited