Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

PushFileService(): u'...' is not in local cache #532

Closed
dw opened this Issue Feb 10, 2019 · 3 comments

Comments

Projects
None yet
2 participants
@dw
Copy link
Owner

commented Feb 10, 2019

ansible_tests

Python: 2.6
MODE=ansible VER=2.4.6.0

PLAY [integration/action/transfer_data.yml] ************************************

TASK [file path=/tmp/transfer-data, state=absent] ******************************
ok: [target-debian-1]
ok: [target-centos6-2]
ok: [target-centos7-3]

TASK [action_passthrough method=_transfer_data, kwargs={u'data': {u'I am JSON': True}, u'remote_path': u'/tmp/transfer-data'}] ***
ok: [target-debian-1]
ok: [target-centos6-2]
ok: [target-centos7-3]

TASK [slurp src=/tmp/transfer-data] ********************************************
ok: [target-debian-1]
ok: [target-centos6-2]
ok: [target-centos7-3]

TASK [assert that=out.content|b64decode == '{"I am JSON": true}'
] *************
ok: [target-debian-1] => {
  changed: False
  failed: False
  msg: All assertions passed
}
ok: [target-centos6-2] => {
  changed: False
  failed: False
  msg: All assertions passed
}
ok: [target-centos7-3] => {
  changed: False
  failed: False
  msg: All assertions passed
}

TASK [action_passthrough method=_transfer_data, kwargs={u'data': u'I am text.', u'remote_path': u'/tmp/transfer-data'}] ***
ok: [target-debian-1]
ok: [target-centos6-2]
ok: [target-centos7-3]

TASK [slurp src=/tmp/transfer-data] ********************************************
ok: [target-debian-1]
ok: [target-centos6-2]
ok: [target-centos7-3]

TASK [assert that=out.content|b64decode == 'I am text.'] ***********************
ok: [target-debian-1] => {
  changed: False
  failed: False
  msg: All assertions passed
}
ok: [target-centos6-2] => {
  changed: False
  failed: False
  msg: All assertions passed
}
ok: [target-centos7-3] => {
  changed: False
  failed: False
  msg: All assertions passed
}

TASK [file path=/tmp/transfer-data, state=absent] ******************************
changed: [target-debian-1]
changed: [target-centos6-2]
changed: [target-centos7-3]

PLAY [integration/async/multiple_items_loop.yml] *******************************

TASK [start long running ops _raw_params={{item}}, _uses_shell=True] ***********
changed: [target-debian-1] => (item=sleep 3; echo hi-from-job-1)
changed: [target-centos6-2] => (item=sleep 3; echo hi-from-job-1)
changed: [target-debian-1] => (item=sleep 5; echo hi-from-job-2)
changed: [target-centos7-3] => (item=sleep 3; echo hi-from-job-1)
changed: [target-centos6-2] => (item=sleep 5; echo hi-from-job-2)
ERROR! [pid 6600] 03:30:05.909573 E mitogen.ctx.fork.78: mitogen: PushFileService(): u'/home/travis/virtualenv/python2.6.9/lib/python2.6/site-packages/ansible/modules/commands/command.py' is not in local cache
changed: [target-centos7-3] => (item=sleep 5; echo hi-from-job-2)

TASK [Ensure static files are collected and compressed jid={{ item.ansible_job_id }}] ***
FAILED - RETRYING: Ensure static files are collected and compressed (30 retries left).
FAILED - RETRYING: Ensure static files are collected and compressed (30 retries left).
FAILED - RETRYING: Ensure static files are collected and compressed (30 retries left).
changed: [target-centos7-3] => (item={'_ansible_parsed': True, u'changed': True, '_ansible_no_log': False, u'ansible_job_id': u'c4c986b8f062476f', 'item': u'sleep 3; echo hi-from-job-1', u'started': 1, '_ansible_item_result': True, 'failed': False, u'finished': 0, '_ansible_ignore_errors': None})
changed: [target-centos6-2] => (item={'_ansible_parsed': True, u'changed': True, '_ansible_no_log': False, u'ansible_job_id': u'b09812d810d2da58', 'item': u'sleep 3; echo hi-from-job-1', u'started': 1, '_ansible_item_result': True, 'failed': False, u'finished': 0, '_ansible_ignore_errors': None})
changed: [target-debian-1] => (item={'_ansible_parsed': True, u'changed': True, '_ansible_no_log': False, u'ansible_job_id': u'83670a2c6dcbef75', 'item': u'sleep 3; echo hi-from-job-1', u'started': 1, '_ansible_item_result': True, 'failed': False, u'finished': 0, '_ansible_ignore_errors': None})
FAILED - RETRYING: Ensure static files are collected and compressed (30 retries left).
changed: [target-centos6-2] => (item={'_ansible_parsed': True, u'changed': True, '_ansible_no_log': False, u'ansible_job_id': u'd990415a4afb0a7c', 'item': u'sleep 5; echo hi-from-job-2', u'started': 1, '_ansible_item_result': True, 'failed': False, u'finished': 0, '_ansible_ignore_errors': None})
changed: [target-debian-1] => (item={'_ansible_parsed': True, u'changed': True, '_ansible_no_log': False, u'ansible_job_id': u'7977e7b38737064e', 'item': u'sleep 5; echo hi-from-job-2', u'started': 1, '_ansible_item_result': True, 'failed': False, u'finished': 0, '_ansible_ignore_errors': None})
FAILED - RETRYING: Ensure static files are collected and compressed (29 retries left).
failed: [target-centos7-3] (item={'_ansible_parsed': True, u'changed': True, '_ansible_no_log': False, u'ansible_job_id': u'42e3e0acea84d390', 'item': u'sleep 5; echo hi-from-job-2', u'started': 1, '_ansible_item_result': True, 'failed': False, u'finished': 0, '_ansible_ignore_errors': None}) => {
  ansible_job_id: 42e3e0acea84d390
  attempts: 3
  changed: False
  failed: 1
  finished: 1
  invocation: {
    module_args: {
      jid: 42e3e0acea84d390
      mode: status
    }
  }
  item: {
    ansible_job_id: 42e3e0acea84d390
    changed: True
    failed: False
    finished: 0
    item: sleep 5; echo hi-from-job-2
    started: 1
  }
  msg: Job reached maximum time limit of 15 seconds.
}

NO MORE HOSTS LEFT *************************************************************

PLAY RECAP *********************************************************************
target-centos6-2           : ok=130  changed=31   unreachable=0    failed=0   
target-centos7-3           : ok=133  changed=31   unreachable=0    failed=1   
target-debian-1            : ok=135  changed=41   unreachable=0    failed=0   

Trigger nasty process pileup ------------------------------------------- 86.62s
Ensure static files are collected and compressed ----------------------- 15.23s
Gathering Facts --------------------------------------------------------- 4.60s
Find regular homedir ---------------------------------------------------- 0.78s
Find out root's homedir. ------------------------------------------------ 0.66s
Get auth token ---------------------------------------------------------- 0.52s
Try writing to temp directory for the readonly_homedir user ------------- 0.51s
Create file tree -------------------------------------------------------- 0.34s
start long running ops -------------------------------------------------- 0.25s
Copy files from content: arg -------------------------------------------- 0.15s
Command exited with non-zero status 2
71.73user 8.36system 2:22.72elapsed 56%CPU (0avgtext+0avgdata 105956maxresident)k
1256inputs+2528outputs (6major+1883940minor)pagefaults 0swaps
travis_time:end:0958507e:start=1549769260347002334,finish=1549769421345887159,duration=160998884825
�[0K�[31;1mThe command ".ci/${MODE}_tests.py" exited with 1.�[0m

travis_fold:start:cache.2
�[0Kstore build cache
travis_time:start:10ccba38
�[0Ktravis_time:end:10ccba38:start=1549769421351499492,finish=1549769421355115951,duration=3616459
�[0Ktravis_time:start:1034d390
�[0K�[32;1mnothing changed, not updating cache�[0m
travis_time:end:1034d390:start=1549769421359668746,finish=1549769424013813097,duration=2654144351
�[0Ktravis_fold:end:cache.2
�[0K

Done. Your build exited with 1.

@dw dw added evergreen osa labels Feb 10, 2019

@jmreicha

This comment has been minimized.

Copy link

commented Feb 11, 2019

Seeing a similar error on a new run after upgrading to v0.2.4.

TASK [workers : Label worker node] ***********************************************************************
Sunday 10 February 2019  17:30:20 -0800 (0:00:00.481)       0:01:19.315 *******
ERROR! [pid 121839] 17:30:27.787325 E mitogen.ctx.ssh.kube-master: mitogen: PushFileService(): '/home/jmreicha/.pyenv/versions/3.7.0/lib/python3.7/site-packages/ansible/modules/commands/command.py' is not in local cache
ERROR! [pid 121839] 17:30:27.788915 E mitogen.ctx.ssh.kube-master: mitogen: PushFileService(): '/home/jmreicha/.pyenv/versions/3.7.0/lib/python3.7/site-packages/ansible/modules/commands/command.py' is not in local cache

@dw dw pinned this issue Feb 11, 2019

@dw

This comment has been minimized.

Copy link
Owner Author

commented Feb 11, 2019

@dw dw changed the title async/multiple_items_loop.yml random failure PushFileService(): u'...' is not in local cache Feb 11, 2019

dw added a commit that referenced this issue Feb 13, 2019

issue #532: PushFileService race.
There has always been a race in PushFileService since given a parent
asked to forward modules to two children via some intermediary:

    interm = router.local()
    c1 = router.local(via=interm)
    c2 = router.local(via=interm)

    service.propagate_to(c1, 'foo/bar.py')
    service.propagate_to(c2, 'foo/bar.py')

Two calls will be emitted to 'interm':

    PushFileService.store_and_forward(c1, 'foo/bar.py', [blob])
    PushFileService.store(c2, 'foo/bar.py')

Which will be processed in-order up to the point where service pool
threads in 'interm' are woken to process the message.

While it is guaranteed store_and_forward() will be processed first, no
guarantee existed that its assigned pool thread would wake and take
_lock first, thus it was possible for forward() to win the race, and for
a request to arrive to forward a file that had not been placed in local
cache yet.

Here we get rid of SerializedInvoker entirely, as it is partially to
blame for hiding the race: SerializedInvoker can only ensure no two
messages are processed simultaneously, it cannot ensure the messages are
processed in their intended order.

Instead, teach forward() that it may be called before
store_and_forward(), and if that is the case, to place the forward
request on to _waiters alongside any local threads blocked in get().

@dw dw closed this in cf8ecf1 Feb 13, 2019

dw added a commit that referenced this issue Feb 13, 2019

Merge remote-tracking branch 'origin/dmw'
* origin/dmw:
  docs: update Changelog.
  core: serialize calls to _service_stub_main().
  docs: update Changelog; closes #532.
  issue #532: PushFileService race.
  docs: more concise Changelog.
  issue #541: changelog typos.
  ansible: quiesce boto logger; closes #541.
@dw

This comment has been minimized.

Copy link
Owner Author

commented Feb 13, 2019

sorry for the hassle, this is on master now :) New release by Monday at the latest. Thanks for letting me know this was hurting you


This is now on the master branch and will make it into the next release. To be updated when a new release is made, subscribe to https://www.freelists.org/list/mitogen-announce

Thanks for reporting this!

@dw dw unpinned this issue Feb 13, 2019

dw added a commit that referenced this issue Feb 14, 2019

Merge remote-tracking branch 'origin/dmw' into stable
* origin/dmw:
  issue #537: disable just the trivial LinuxPolicyTest on Travis.
  docs: update Changelog; closes #537.
  ansible: refactor affinity class and add abstract tests.
  Bump version for release.
  docs: update Changelog.
  core: serialize calls to _service_stub_main().
  docs: update Changelog; closes #532.
  issue #532: PushFileService race.
  docs: more concise Changelog.
  issue #541: changelog typos.
  ansible: quiesce boto logger; closes #541.
  docs: update Changelog.
  tests/ansible: Spec.port() test & mitogen_via= fix.
  Update copyright year everywhere.
  tests/ansible: Spec.become_pass() test.
  docs: remove top "Table of Contents" link
  docs: remove a little more top margin wastage
  tests/ansible: Spec.become_user() test.
  docs: update Changelog; closes #539.
  issue #539: disable logger propagation.
  ansible: capture stderr stream of async tasks. Closes #540.
  docs: update Changelog.
  issue #536: rework how 2.3-compatible simplejson is served
  .github: add some more questions to issue template
  docs: duplicate word
  docs: update Changelog.
  tests/ansible: Spec.become_method() test & mitogen_via= fix.
  setup.py: include LICENSE; closes #538.
  tests/ansible: Spec.become() test
  tests/ansible: Spec.password() test, document interactive pw limitation.
  tests/ansible: Spec.remote_user() test & mitogen_via= fix.
  tests/ansible: Spec.remote_addr() test & mitogen_via= fix.
  tests/ansible: Spec.transport() test.
  docs: lighter pink
  docs: add 'Fixes' heading
  docs: more margin tweaks for changelog
  docs: tighter <p> margins, even less shouting, red headings
  docs: tidy up footer and GitHub link
  docs: enable fixed_sidebar
  docs: sans-serif fonts, reduce shouty headings
  issue #536: add mitogen_via= tests too.
  ansible: fix a crash on 2.3 when mitogen_via= host is missing.
  tests: for 2.3 compatibility, disable gcloud.py for now
  docs: update Changelog; closes #511, closes #536.
  docs: update Changelog release date.
  issue #536: disable transport_config tests on vanilla
  issue #536: restore correct Python interpreter selection behaviour.
  issue #536: connection_delegation/ tests were erroneously broken
  tests: define MITOGEN_INVENTORY_FILE even if -i unspecified.
  issue #536: add tests for each ansible_python_interpreter case.
  issue #536: stop defining explicit localhost in inventory.
  tests: allow running Ansible tests locally without -udmw again.
  stable: fix preamble_size on stable docs.
  issue #481: add test.

dw added a commit that referenced this issue Feb 25, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.