sr_watch fails with high sample volumes in flow test

benlapETS commented 5 years ago

SUMMARY

3 cases identified so far:

KeyError (ObservedWatch) case: This is the most difficult to trace and understand, but the easiest to resolve. Maybe it is a race condition in watchdog and/or conjugate to a sluggish stop_instance routine. The fact is that refactoring stop_instance in a more pythonic way solve the problem.
OSError("inotify watch limit reached") case: This is thrown when the sysctl inotify max has been reached the easiest work around is to increase the max, but what would be the drawback of doing that on long run. I started a separate issue #204 to document a bit more that case. I could write unit test for different inotify max and track the performances resutls.
FileNotFoundError case: This is when somebody delete (maliciously or unintentionally) the data being watched and I resolved it by stopping doing (unintentionnal) chaos delete. This is easy to reproduce and unit test could be written enough easily. The fact is that this could happen and if there is no external process to identify the failure, Sarra could be use as a tool to detect such action because it would quickly react to it and it could trigger some recovery strategy. But that had nothing to do with high sample volumes, we could either solve it here, discard it or open a separate issue for it.
IndexError case: This is happening when hb_memory restart watch and for a reason that I still ignore file_total variables does not exist anymore. The plugin crash on restart and so sr_watch.

With changes (1.fixed rm cron jobs, 2.reject enable in no_trouble, 3.walk, 4.stop_instances, 5.fs.inotify max up) made so far:

1 000 sample still succeed
3 000 sample failed at f62 (sr_poll)
5 000 sample failed at f62 (sr_poll)
10 000 sample failed at f62 (sr_poll) + sr_watch posted 200k msgs
100 000 sample failed at sarra, watch, veille, subscribers, post, shovel(f90-92)

Reverting changes of this issue (but keeping fs.inotify max up):

5 000 sample failed at pclean (both 90, 92)
10 000 sample failed at pclean92
100 000 (109 444) sample failed at watch, veille, sender, subscribers(f60-61), shovel(f90-92),

Too many things goes wrong I will most certainly abandon the fixes I provided for that issue and restart from scratch focusing on the 3 failures I've identified so far then providing code test to reproduce effectively and provide a way to fix it with the least impact on the code. Flow test is a good integration test, testing if everything is ok but not a good reference to test particular issues because it will not always reproduce the context of a particular issue, this is why I need to redo the whole thing, understanding this problem and expectation, writing tests with outcomes expected and writing code or directive for config to meet expectations. I identified a flaw of the flow test in that issue #206

benlapETS commented 5 years ago

Also caught that warning on a normal run which was also mention in #179:

 1 sr_watch_f40_01.log [WARNING] sr_watch priming watch: /local/ben/sarra_devdocroot/downloaded_by_sub_t failed, deferred.

I'm not sure if it may be related.

Note 2: Don't think it related to the bug but I easily fixed it, we were declaring self.inl as a list while trying to use it as a dict. Don't know what it will change

benlapETS commented 5 years ago

Another try with a 10 000 sample gave me a lot of errors, and I draw the parallel with this case because of this:

2019-05-01 11:25:21,578 [ERROR] Traceback (most recent call last):
2019-05-01 11:25:21,578 [ERROR]   File "/local/ben/anaconda3/envs/base_sarra/bin/sr_watch", line 11, in <module>
2019-05-01 11:25:21,578 [ERROR] load_entry_point('metpx-sarracenia', 'console_scripts', 'sr_watch')()
2019-05-01 11:25:21,578 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_watch.py", line 65, in main
2019-05-01 11:25:21,947 [ERROR] watch.exec_action(action,old)
2019-05-01 11:25:21,947 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_instances.py", line 301, in exec_action
2019-05-01 11:25:23,547 [ERROR] elif action == 'start'      : self.start_parent()
2019-05-01 11:25:23,547 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_instances.py", line 785, in start_parent
2019-05-01 11:25:23,547 [ERROR] self.start()
2019-05-01 11:25:23,547 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1459, in start
2019-05-01 11:25:23,548 [ERROR] self.run()
2019-05-01 11:25:23,548 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1446, in run
2019-05-01 11:25:23,548 [ERROR] if self.sleep > 0: self.watch_loop()
2019-05-01 11:25:23,548 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1264, in watch_loop
2019-05-01 11:25:23,549 [ERROR] self.wakeup()
2019-05-01 11:25:23,549 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1141, in wakeup
2019-05-01 11:25:23,550 [ERROR] done = self.process_event( event, src, dst )
2019-05-01 11:25:23,550 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1030, in process_event
2019-05-01 11:25:23,550 [ERROR] lstat = os.stat(src)
2019-05-01 11:25:23,550 [ERROR] FileNotFoundError
2019-05-01 11:25:23,550 [ERROR] :
2019-05-01 11:25:23,550 [ERROR] [Errno 2] No such file or directory: '/local/ben/sarra_devdocroot/downloaded_by_sub_t/20190501/WXO-DD/hydrometric/csv/NL/hourly/NL_03OE013_hourly_hydrometric.csv.tmp'

I think I begin to sense the problem here, we first check if the file exist (which it does so it pass) and then the file get deleted before we got to os.stat. There is a race condition here (and surely elsewhere in sr_watch), it might be the same problem with the base issue. I believe it would be safer to try except in those cases, log the error temporarily and see if we can get a broader solution that would prevent that from happening.

It would be smart to draw the timeline of those many concurrent pipe in details to identify the risks of those race condition situation before we try to fix that for real because :

It would help us to have a better understanding of this particular view of our architecture
With that understanding at hand we would design a much better system, more resilient
We would then be able to identify test cases more clearly and write test case specific to that problem so we would avoid any set back of new features trying to add more concurency.

petersilva commented 5 years ago

go look in sarra/examples/*.inc reenable the rejects of moving targets. There is a whole series of them. These are files which keep the same name and are constantly overwritten, the clean jobs are broken in that they delete old versions of the files... even through new ones are still flowing... I thought we didn´t need them anymore, but apparently we do. See if the runs are now clean...

Another thing to try later is to just exclude the moving targets from the pclean processes. but first lets make sure we have caught the problem with the above change.

petersilva commented 5 years ago

2019-05-02 15:38:38,535 [INFO] sr_watch f40 01 starting
Fatal Python error: Cannot recover from stack overflow.

Current thread 0x00007faa9536d740 (most recent call first):
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  File "/usr/lib/python3.6/logging/__init__.py", line 917 in handleError
  File "/usr/lib/python3.6/logging/__init__.py", line 1000 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 1072 in emit
  File "/usr/lib/python3.6/logging/handlers.py", line 73 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 865 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1516 in callHandlers
  File "/usr/lib/python3.6/logging/__init__.py", line 1454 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1444 in _log
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  File "/usr/lib/python3.6/logging/__init__.py", line 917 in handleError
  File "/usr/lib/python3.6/logging/__init__.py", line 1000 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 1072 in emit
  File "/usr/lib/python3.6/logging/handlers.py", line 73 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 865 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1516 in callHandlers
  File "/usr/lib/python3.6/logging/__init__.py", line 1454 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1444 in _log
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  File "/usr/lib/python3.6/logging/__init__.py", line 917 in handleError
  File "/usr/lib/python3.6/logging/__init__.py", line 1000 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 1072 in emit
  File "/usr/lib/python3.6/logging/handlers.py", line 73 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 865 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1516 in callHandlers
  File "/usr/lib/python3.6/logging/__init__.py", line 1454 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1444 in _log
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  File "/usr/lib/python3.6/logging/__init__.py", line 917 in handleError
  File "/usr/lib/python3.6/logging/__init__.py", line 1000 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 1072 in emit
  File "/usr/lib/python3.6/logging/handlers.py", line 73 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 865 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1516 in callHandlers
  File "/usr/lib/python3.6/logging/__init__.py", line 1454 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1444 in _log
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  File "/usr/lib/python3.6/logging/__init__.py", line 917 in handleError
  File "/usr/lib/python3.6/logging/__init__.py", line 1000 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 1072 in emit
  File "/usr/lib/python3.6/logging/handlers.py", line 73 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 865 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1516 in callHandlers
  File "/usr/lib/python3.6/logging/__init__.py", line 1454 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1444 in _log
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  File "/usr/lib/python3.6/logging/__init__.py", line 917 in handleError
  File "/usr/lib/python3.6/logging/handlers.py", line 75 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 865 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1516 in callHandlers
  File "/usr/lib/python3.6/logging/__init__.py", line 1454 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1444 in _log
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  File "/usr/lib/python3.6/logging/__init__.py", line 917 in handleError
  File "/usr/lib/python3.6/logging/__init__.py", line 1000 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 1072 in emit
  File "/usr/lib/python3.6/logging/handlers.py", line 73 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 865 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1516 in callHandlers
  File "/usr/lib/python3.6/logging/__init__.py", line 1454 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1444 in _log
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  File "/usr/lib/python3.6/logging/__init__.py", line 917 in handleError
  File "/usr/lib/python3.6/logging/__init__.py", line 1000 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 1072 in emit
  File "/usr/lib/python3.6/logging/handlers.py", line 73 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 865 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1516 in callHandlers
  File "/usr/lib/python3.6/logging/__init__.py", line 1454 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1444 in _log
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  File "/usr/lib/python3.6/logging/__init__.py", line 917 in handleError
  File "/usr/lib/python3.6/logging/__init__.py", line 1000 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 1072 in emit
  File "/usr/lib/python3.6/logging/handlers.py", line 73 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 865 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1516 in callHandlers
  File "/usr/lib/python3.6/logging/__init__.py", line 1454 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1444 in _log
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  File "/usr/lib/python3.6/logging/__init__.py", line 917 in handleError
  File "/usr/lib/python3.6/logging/__init__.py", line 1000 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 1072 in emit
  File "/usr/lib/python3.6/logging/handlers.py", line 73 in emit
  File "/usr/lib/python3.6/logging/__init__.py", line 865 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1516 in callHandlers
  File "/usr/lib/python3.6/logging/__init__.py", line 1454 in handle
  File "/usr/lib/python3.6/logging/__init__.py", line 1444 in _log
  File "/usr/lib/python3.6/logging/__init__.py", line 1374 in log
  File "/usr/lib/python3/dist-packages/sarra/sr_config.py", line 85 in write
  ...
sanity check: log file /local/home/peter/.cache/sarra/log/sr_cpost_veille_f34_01.log untouched in 598 seconds (too long.)
parent exiting normally, rest is upto the child pid: 29250
config pelle_dd2_f05 is stopped.

petersilva commented 5 years ago

previous entry was printed when... I started flow_check, then killed sr_watch in order to run sr sanity and confirm it got restarted... some time later the crash message above showed up. not sure of relevance.

benlapETS commented 5 years ago

Not sure either that it is relevant to that issue : did you wait for high volume samples ? 10 000 ? 100 000 ? before that happened ?

Is it a normal thing to kill sr_watch in the middle of process ?

The error pointed out looks like a bad recursion because of the StreamToLogging redirection thing implemented for the Windows issue... (#112 ??)

Update: I opened a new bug report #202

petersilva commented 5 years ago

The thing was running for a few hours (because I forgot about) after it had been restarted, that´s why I copy/pasted it, thinking it is a related to the long run. the weird thing is that it printed out to the tty where I ran sr sanity... so that logging not being quite re-directed is still dogging us.

petersilva commented 5 years ago

I still think the first thing to do is to put the rejects of the moving targets back into the include files, and see if things clean up a lot.

benlapETS commented 5 years ago

For the KeyError case, the root cause seems to be the double stop signal that is thrown to sr_watch:

sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,221 [INFO] signal stop (SIGTERM)
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,722 [INFO] signal stop (SIGTERM)

The first stop goes to the lock I have purposely put in the close sequence for testing:

sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,730 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_instances.py", line 1011, in stop_signal
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,731 [ERROR] self.stop()
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,731 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1468, in stop
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,732 [ERROR] self.close()
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,732 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 159, in close
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,732 [ERROR] self.observer.join()
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,732 [ERROR]   File "/local/ben/anaconda3/envs/base_sarra/lib/python3.7/threading.py", line 1032, in join
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,734 [ERROR] self._wait_for_tstate_lock()
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,734 [ERROR]   File "/local/ben/anaconda3/envs/base_sarra/lib/python3.7/threading.py", line 1048, in _wait_for_tstate_lock
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,734 [ERROR] elif lock.acquire(block, timeout):

The second stop signal failed because the watch has been handled by the first but the list obs_watched still contains the keys:

sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,734 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_instances.py", line 1011, in stop_signal
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,735 [ERROR] self.stop()
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,735 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1468, in stop
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,736 [ERROR] self.close()
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,736 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 157, in close
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,736 [ERROR] self.observer.unschedule(ow)
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,736 [ERROR]   File "/local/ben/anaconda3/envs/base_sarra/lib/python3.7/site-packages/watchdog/observers/api.py", line 343, in unschedule
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,737 [ERROR] emitter = self._emitter_for_watch[watch]
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,737 [ERROR] KeyError
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,737 [ERROR] :
sr_watch_f40_01.log.2019-05-03:2019-05-03 18:52:20,737 [ERROR] <ObservedWatch: path=/local/ben/sarra_devdocroot/downloaded_by_sub_t, is_recursive=True>

benlapETS commented 5 years ago

Finally I think I was off track (and negligent), the real root cause was sarra_devdocroot that was deleted every 40 min from a forgotten cron job. Should we prevent a crash if a user accidentally delete (not as dumbly as me) his Watched folder ?

petersilva commented 5 years ago

Google chaos monkey. You're ahead of the game!

benlapETS commented 5 years ago

I got rid of my chaos monkey noise and it still failed. Here is a view on what is going on:

Hb_memory first trigger a restart cmd, then 3 stop signals are sent and the restart command failed:

2019-05-06 18:10:05,582 [INFO] hb_memory cpu_times user=235.67 system=14.57 elapse=17215891.3
2019-05-06 18:10:05,582 [INFO] hb_memory, current usage: 276.4 MiB trigger restart if increases past: 276.3 MiB 
2019-05-06 18:10:05,582 [INFO] hb_memory triggering ['sr_watch', '--no', '1', '/local/ben/.config/sarra/watch/f40.conf', 'restart']
2019-05-06 18:10:05,783 [INFO] signal stop (SIGTERM)
2019-05-06 18:10:05,783 [INFO] sr_watch stop
2019-05-06 18:10:06,285 [INFO] signal stop (SIGTERM)
2019-05-06 18:10:06,285 [INFO] sr_watch stop
2019-05-06 18:10:08,827 [INFO] signal stop (SIGTERM)
2019-05-06 18:10:08,828 [INFO] sr_watch stop
2019-05-06 18:10:08,832 [ERROR] trying run command sr_watch --no 1 /local/ben/.config/sarra/watch/f40.conf restart

sr_watch publisher is then put to sleep and then reconnect:

2019-05-06 18:10:08,833 [INFO] hb_pulse message_count 0 publish_count 32979 
2019-05-06 18:10:08,833 [INFO] hb_cache was 2778, but since 65.13 sec, increased up to 0, now saved 0 entries
2019-05-06 18:10:08,836 [ERROR] sr_amqp/publish: Sleeping 5 seconds ... and reconnecting
2019-05-06 18:10:13,840 [INFO] Using amqp module (AMQP 0-9-1)

a new stop signal is sent 9 minutes later and sr_watch crashes:

2019-05-06 18:19:29,379 [INFO] signal stop (SIGTERM)
2019-05-06 18:19:29,379 [INFO] sr_watch stop
2019-05-06 18:19:29,379 [ERROR] Traceback (most recent call last):
2019-05-06 18:19:29,379 [ERROR]   File "/local/ben/anaconda3/envs/base_sarra/bin/sr_watch", line 11, in <module>
2019-05-06 18:19:29,380 [ERROR] load_entry_point('metpx-sarracenia', 'console_scripts', 'sr_watch')()
2019-05-06 18:19:29,380 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_watch.py", line 65, in main
2019-05-06 18:19:29,419 [ERROR] watch.exec_action(action,old)
2019-05-06 18:19:29,419 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_instances.py", line 301, in exec_action
2019-05-06 18:19:29,419 [ERROR] elif action == 'start'      : self.start_parent()
2019-05-06 18:19:29,419 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_instances.py", line 785, in start_parent
2019-05-06 18:19:29,419 [ERROR] self.start()
2019-05-06 18:19:29,419 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1464, in start
2019-05-06 18:19:29,420 [ERROR] self.run()
2019-05-06 18:19:29,420 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1451, in run
2019-05-06 18:19:29,420 [ERROR] self.watch_loop()
2019-05-06 18:19:29,420 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1272, in watch_loop
2019-05-06 18:19:29,421 [ERROR] time.sleep(self.sleep-elapse)
2019-05-06 18:19:29,421 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_instances.py", line 1011, in stop_signal
2019-05-06 18:19:29,421 [ERROR] self.stop()
2019-05-06 18:19:29,421 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 1468, in stop
2019-05-06 18:19:29,421 [ERROR] self.close()
2019-05-06 18:19:29,421 [ERROR]   File "/local/ben/git/sarracenia/sarra/sr_post.py", line 157, in close
2019-05-06 18:19:29,421 [ERROR] self.observer.unschedule(ow)
2019-05-06 18:19:29,421 [ERROR]   File "/local/ben/anaconda3/envs/base_sarra/lib/python3.7/site-packages/watchdog/observers/api.py", line 343, in unschedule
2019-05-06 18:19:29,500 [ERROR] emitter = self._emitter_for_watch[watch]
2019-05-06 18:19:29,500 [ERROR] KeyError
2019-05-06 18:19:29,500 [ERROR] :
2019-05-06 18:19:29,500 [ERROR] <ObservedWatch: path=/local/ben/sarra_devdocroot/downloaded_by_sub_t, is_recursive=True>

My questions are:

Why is the restart cmd triggering 3 stop signal, and why the cmd failed ?
Is the publisher sleep has anything to do with that sequence ?
Why is there a 4th stop signal sent and where does it came from ? Is it related to the first 3 ? Why is this one succeeded ?
Is there a reason why it failed exactly 2h (18:19:30 - 16:19:31=1h59m59s) after the start ? That seems odd...
Then, the most important question, why sr_watch crashed with a KeyError ?

Michel intuition is that the stop occured in the child which doesn't share the observer of the parent, in which the watch exists.

Then I need to make a new run (a 2h run) to verify that theory and try to answer those fishy behaviours. I will add pid to the logging and run in debug for sr_watch.

petersilva commented 5 years ago

f40 is explicitly set with heartbeat 60, and hb_memory_multiplier 1.02 to make it very likely to have an automatically triggerred restart. Ensuring the restart works would be a good thing. I think if you look at the stop logic, it might be just that it looks, see it hasn´t gone away, and then loops trying to kill it... (sr_instances/stop_instance) ...

benlapETS commented 5 years ago

Here is a summary of what I went through last week, following the questions that I was asking myself:

stop_signal triggering is part of sr_instance.stop_instance method where there is a kill loop using SIGTERM for a maximum of 4 attempt (0.5, 1, 2, 4)secs < 7secs and a final kill (SIGKILL) only if fourth attempt failed.
I didnt see any sign that the error with amqp reconnection was inducing any of the remaining errors for now. In fact, I presume that this failsafe is purposely detecting that the amqp connection is down because channels has been close during the aborted restart sequence.
As I recreated the problem with a hb memory multiplier much lower (1.0001) I cannot know if the 2 hour exact fail time has anything to do with the understanding of the problem.
I see that KeyError as a result of a race condition between two process that entered the restart sequences so when the second try to unschedule the watch it is not there anymore.

I think I am close to provide a fix but still without a full understanding of the real problem so I am still very careful.

Here are 2 useful cmd to filter logs relative to that issue:

grep -B 4 -A 100 "hb_memory triggering" *.log* | less
cat flowsetup_f00.log* | grep -v in-event | less

Cmd to count different errors and warnings:

grep ERROR *.log* | egrep -h -o "ERROR] *[^ ]+" | sort | uniq -c
grep WARNING *.log* | grep -h -o "WARNING] \+$HOME\|WARNING] \+[a-zA-Z0-9]*" | sort | uniq -c

benlapETS commented 5 years ago

I will investigate on this tomorrow, why is there always 3 child to sr_watch like that:

Note (May 14): I've seen that the 3 child under sr_watch are managed by watchdog, so for now it seems like a bit out of my scope as I effectively corrected all crashes that were occurring. If we ever see race condition problems occuring in watch because of that we will know where to point at...

benlapETS commented 5 years ago

This diagram is a view on the hb_memory restart trigger sequence on srwatch (which would be similar to other sr and the same of sr_post). It is INCOMPLETE for now.

benlapETS commented 5 years ago

Here is a view on how SIGTERM may be managed (still INCOMPLETE diagram)

benlapETS commented 5 years ago

Note1: This morning, Michel gave me a hint pointing to shovels (pclean) plugin that might be creating inotify event when switching over testid (copy, slink, hlink, moved).
Note2: I also started to investigate the way flow_check (specifically flow_include) compute watches count where there seems to have flaws when running long tests.
Note3: I found that using log rotation could mislead a tester (at least it did for me) of the real count vs what sumlog computes for msg, post and file which are computed from their respective plugin. It introduce too complex cases handling which I want to discuss in this new issue #206 .

benlapETS commented 5 years ago

Note1: New case identified, hb_memory will restart watch because memory limit reached, but at restart it reads post_total_save .vars but it is empty, so it cannot recover anything. Added a check in the plugin that will prevent that and log the error for now. This will not really fix it. Note2: Cases in this issue are now handle properly. I will try to merge fixes from this branch. Need to wait for the result of the pull request tests, but also running some tests on local machine.

MetPX / sarracenia

sr_watch fails with high sample volumes in flow test #182

SUMMARY