"wrong-type-argument hash-table-p nil" when opening a buffer to write a commit message in magit (duplicate with #26)

[shackra]

Was on a magit-status committing some changes and when opening the COMMIT_EDITMSG buffer I experience that error, there is the backtrace:

Debugger entered--Lisp error: (wrong-type-argument hash-table-p nil)
  profiler-cpu-log()
  (profiler-make-profile :type 'cpu :timestamp (current-time) :log (profiler-cpu-log))
  explain--save-and-stop-profiling()
  (let ((profile (explain--save-and-stop-profiling))) (if too-long (progn (explain--store-profile now-snap diff command-set profile))))
  (progn (let ((profile (explain--save-and-stop-profiling))) (if too-long (progn (explain--store-profile now-snap diff command-set profile)))))
  (if was-profiled (progn (let ((profile (explain--save-and-stop-profiling))) (if too-long (progn (explain--store-profile now-snap diff command-set profile))))))
  (let* ((now-snap (current-time)) (diff (explain--as-ms-exact (time-subtract now-snap before-snap))) (too-long (> diff explain-pause-slow-too-long-ms))) (if was-profiled (progn (let ((profile (explain--save-and-stop-profiling))) (if too-long (progn (explain--store-profile now-snap diff command-set profile)))))) (setq executing-command original-execution-command) (run-hook-with-args 'explain-pause-measured-command-hook diff 0 command-set (and was-profiled too-long)) (if (or too-long (symbol-value diff-override)) (progn (explain--log-pause diff 0 command-set nil nil) (if too-long (progn (explain--increment-profile command-set))))))
  (let ((before-snap (current-time))) (apply measure-func args) (let* ((now-snap (current-time)) (diff (explain--as-ms-exact (time-subtract now-snap before-snap))) (too-long (> diff explain-pause-slow-too-long-ms))) (if was-profiled (progn (let ((profile (explain--save-and-stop-profiling))) (if too-long (progn (explain--store-profile now-snap diff command-set profile)))))) (setq executing-command original-execution-command) (run-hook-with-args 'explain-pause-measured-command-hook diff 0 command-set (and was-profiled too-long)) (if (or too-long (symbol-value diff-override)) (progn (explain--log-pause diff 0 command-set nil nil) (if too-long (progn (explain--increment-profile command-set)))))))
  (let ((original-execution-command executing-command) (was-profiled (and (not profiling-command) (explain--profile-p command-set)))) (setq executing-command command-set) (if was-profiled (progn (explain--start-profiling))) (let ((before-snap (current-time))) (apply measure-func args) (let* ((now-snap (current-time)) (diff (explain--as-ms-exact (time-subtract now-snap before-snap))) (too-long (> diff explain-pause-slow-too-long-ms))) (if was-profiled (progn (let ((profile ...)) (if too-long (progn ...))))) (setq executing-command original-execution-command) (run-hook-with-args 'explain-pause-measured-command-hook diff 0 command-set (and was-profiled too-long)) (if (or too-long (symbol-value diff-override)) (progn (explain--log-pause diff 0 command-set nil nil) (if too-long (progn (explain--increment-profile command-set))))))))
  (if (not explain-pause-mode) (apply measure-func args) (let ((original-execution-command executing-command) (was-profiled (and (not profiling-command) (explain--profile-p command-set)))) (setq executing-command command-set) (if was-profiled (progn (explain--start-profiling))) (let ((before-snap (current-time))) (apply measure-func args) (let* ((now-snap (current-time)) (diff (explain--as-ms-exact (time-subtract now-snap before-snap))) (too-long (> diff explain-pause-slow-too-long-ms))) (if was-profiled (progn (let (...) (if too-long ...)))) (setq executing-command original-execution-command) (run-hook-with-args 'explain-pause-measured-command-hook diff 0 command-set (and was-profiled too-long)) (if (or too-long (symbol-value diff-override)) (progn (explain--log-pause diff 0 command-set nil nil) (if too-long (progn ...))))))))
  explain--measure-function(server-process-filter (#<process server <5>> "-dir /home/jorge/Documentos/straubinger-digital/jn...") (server-process-filter process-filter) explain-pause-log-all-process-io)
  (closure ((final-command-set server-process-filter process-filter) (original-callback . server-process-filter) (command-set process-filter) explain-pause-top-mode-abbrev-table explain-pause-top-mode-syntax-table cl-struct-explain-pause-top--command-entry-tags cl-struct-explain-pause-top--table-display-entry-tags cl-struct-explain-pause-top--table-tags t) (&rest callback-args) (explain--measure-function original-callback callback-args final-command-set 'explain-pause-log-all-process-io))(#<process server <5>> "-dir /home/jorge/Documentos/straubinger-digital/jn...")

this error does not pop always, just from time to time. My Emacs version is GNU Emacs 28.0.50 (build 3, x86_64-pc-linux-gnu, GTK+ Version 3.24.14, cairo version 1.17.3) of 2020-02-18

[lastquestion]

Hey @shackra !! Two bug reports, I'm so sorry that it's always you :_) But much appreciate for sticking through and trying it out and reporting bugs. ❤️

I wonder if this is because of that bug fix that @wasamasa did in https://debbugs.gnu.org/cgi/bugreport.cgi?bug=22114

emacs-mirror/emacs@9997429#diff-9b8918fcce768417239eefcfb134168a

Hm - no, I don't think so, profiles work in 28.0, I just tried it.

Maybe there is a bug when two guys try to profile at the same time? Let me consider it. I thought I squashed all such bugs but that area of the code isn't well tested so I may have introduced a bug.

[wasamasa]

The problem isn't so much writing a commit message in Magit as using emacsclient. I'm not sure what the exact condition with the daemon is (suspending to disk and waking up?), but at some point I can reliably trigger it.

[lastquestion]

Wait, @shackra , are you on latest HEAD? I deleted was-profiled in the big PR for #42, it doesn't exist anymore. Can you update to HEAD and let me know if you see it again?

[lastquestion]

Before #42, it was 100% possible that explain-pause would get confused when server.el is being used, which it always is used by magit, and then it would either think that profiling was ON when it was OFF or OFF when it was ON.

I think that I fixed that in #42, but I will say I did not yet add tests around that area, so I could have missed something.

@wasamasa - hm. Yes, the daemon is pretty evil in the sense that it sometimes runs interactive code out from a timer or a filter. I thought I have quashed all the bugs related to it. What I will do is - add a check and make report buffer popup in cases when the expected profiling state does not match the real profiling state. Once I do that if you can update to HEAD and next time you hit that please send the reporting buffer 🙏 😢

[shackra]

Wait, @shackra , are you on latest HEAD?

According to straight.el, I'm at 318dace

[shackra]

Now I'm running with ef0ce46 but I will report back during the weekend or before that as this bug is really elusive

[lastquestion]

❤️ let me know. I am going to pull a PR together tonight / tomorrow that will give more debugging information when it actually happens as well, it will print a buffer with full backtrace and lots of internal information so when you do hit it we can fix it!

I definitely did not write proper tests in this area so I'm sorry, it's possible I did not yet fix all the cases in #42 though I think I did. Thank you for testing :_) 💯

[shackra]

this didn't show up anymore

[lastquestion]

I will implement a report-error for when profiling does not match expected state and close this issue with it, that way if it happens more I will have sufficient debugging information to fix why without too much back and forth questions and debugging. Glad to hear it's not happening anymore!

[wasamasa]

Couldn't reproduce this either.