Transaction 404 about 2 seconds after a write.

[MatthewHink]

If we're lucky this is just the transaction TTL being under two seconds.

*** lock_write_test momentary unlock lock at 2020-02-19 16:53:30.355998
*** writing device: 0070391e-2e46-57ec-9277-9cea05b9519c
*** http_post: url: http://10.42.5.72:5000/v3/write/0070391e-2e46-57ec-9277-9cea05b9519c, message_body: {'action': 'pulseUnlock'}
<snip>
*** checking transaction id: 73bf0b88-a675-451a-a019-23d9ec5cc028
[2020-02-19 16:53:32,684] site_tests:31 (ERROR) - Fatal Exception in site-test
Traceback (most recent call last):
  File "site_tests.py", line 25, in main
    test_results = test_synse.synse_test(sys.argv[1])
  File "/home/ubuntu/src/vem-access/burnin/site_tests/synse/synse_test.py", line 1208, in synse_test
    results.extend(lock_async_write_test(site, scan_json))
  File "/home/ubuntu/src/vem-access/burnin/site_tests/synse/synse_test.py", line 1398, in lock_async_write_test
    wait_for_transactions(synse_ip, transaction_ids)
  File "/home/ubuntu/src/vem-access/burnin/site_tests/synse/synse_test.py", line 1231, in wait_for_transactions
    response = http_get(transaction_url).json()
  File "/home/ubuntu/src/vem-access/burnin/site_tests/synse/synse_test.py", line 54, in http_get
    response.raise_for_status()
  File "/usr/lib/python3/dist-packages/requests/models.py", line 935, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: Not Found for url: http://10.42.5.72:5000/v3/transaction/73bf0b88-a675-451a-a019-23d9ec5cc028

lost-transaction-id.txt

[MatthewHink]

Nope - this is me using the device id and not the transaction id.

[MatthewHink]

I'm wrong.
Device id: 0070391e-2e46-57ec-9277-9cea05b9519c
Transaction id: 73bf0b88-a675-451a-a019-23d9ec5cc028
Better trace:

*** lock_write_test momentary unlock lock at 2020-02-19 16:53:30.355998
*** writing device: 0070391e-2e46-57ec-9277-9cea05b9519c
*** http_post: url: http://10.42.5.72:5000/v3/write/0070391e-2e46-57ec-9277-9cea05b9519c, message_body: {'action': 'pulseUnlock'}
*** transaction_id: 73bf0b88-a675-451a-a019-23d9ec5cc028
<snip>
*** lock_write_test waiting for transactions at 2020-02-19 16:53:30.931045
*** checking transaction id: 73bf0b88-a675-451a-a019-23d9ec5cc028
[2020-02-19 16:53:32,684] site_tests:31 (ERROR) - Fatal Exception in site-test
Traceback (most recent call last):
  File "site_tests.py", line 25, in main
    test_results = test_synse.synse_test(sys.argv[1])
  File "/home/ubuntu/src/vem-access/burnin/site_tests/synse/synse_test.py", line 1208, in synse_test
    results.extend(lock_async_write_test(site, scan_json))
  File "/home/ubuntu/src/vem-access/burnin/site_tests/synse/synse_test.py", line 1398, in lock_async_write_test
    wait_for_transactions(synse_ip, transaction_ids)
  File "/home/ubuntu/src/vem-access/burnin/site_tests/synse/synse_test.py", line 1231, in wait_for_transactions
    response = http_get(transaction_url).json()
  File "/home/ubuntu/src/vem-access/burnin/site_tests/synse/synse_test.py", line 54, in http_get
    response.raise_for_status()
  File "/usr/lib/python3/dist-packages/requests/models.py", line 935, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: Not Found for url: http://10.42.5.72:5000/v3/transaction/73bf0b88-a675-451a-a019-23d9ec5cc028

[MatthewHink]

Between this and the linked bug, I cannot normally make it through my lock write test. Considering these both priority 1.

test-stacks.txt

[edaniszewski]

looking into this next

[edaniszewski]

upon further investigation, I found two bugs relating to this:

• the TTL is not properly set for the transaction cache because of an order of operations issue (cache defined globally, config not loaded when module is first initialized). The effects of this are that the TTL is actually getting set to None, which means it will never be cleaned up from the cache.
  • I have a fix for this on a local branch.
• a force scan (e.g. cache rebuild) seems to clear the transaction cache. This is likely what you were running into and is a major bug here and in no way should be happening.
  • Working through this one now. Should probably have a fix shortly.

[edaniszewski]

The cache clear on rebuild is a bug in a dependency: aio-libs/aiocache#479

There is a simple fix for it, will push shortly.