explain-pause--wrap-set-process-sentinel-callback makes Circe connection attempts fail (root cause: `set-process-plist` stomps filter plist arg stored in processes)

[wasamasa]

Backtrace after initial connection attempt:

Debugger entered--Lisp error: (wrong-type-argument arrayp nil)
  (explain-pause--wrap-set-process-sentinel-callback #<subr set-process-sentinel> #<process brause.cc> irc--sentinel)
  (apply explain-pause--wrap-set-process-sentinel-callback #<subr set-process-sentinel> (#<process brause.cc> irc--sentinel))
  (set-process-sentinel #<process brause.cc> irc--sentinel)
  (tls--filter #<process brause.cc> "Processed 0 CA certificate(s).\nResolving 'brause.cc:30832'...\nConnecting to '84.22.118.61:30832'...\n- Certificate type: X.509\n- Got a certificate list of 2 certificates.\n- Certificate[0] info:\n - subject `CN=brause.cc', issuer `CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US', serial 0x036e0cf8338636f52b6d0d93f76268279123, RSA key 4096 bits, signed using RSA-SHA256, activated `2020-06-01 00:01:57 UTC', expires `2020-08-30 00:01:57 UTC', pin-sha256=\"Rek9omuKhVeg6P+JHum2eyiiURpgd1lWrl1uzdyQBkY=\"\n\011Public Key ID:\n\011\011sha1:184ddb2a9480c77da34ebb43d542e634ec8e08b4\n\011\011sha256:45e93da26b8a8557a0e8ff891ee9b67b28a2511a60775956ae5d6ecddc900646\n\011Public Key PIN:\n\011\011pin-sha256:Rek9omuKhVeg6P+JHum2eyiiURpgd1lWrl1uzdyQBkY=\n\n- Certificate[1] info:\n - subject `CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US', issuer `CN=DST Root CA X3,O=Digital Signature Trust Co.', serial 0x0a0141420000015385736a0b85eca708, RSA key 2048 bits, signed using RSA-SHA256, activated `2016-03-17 16:40:46 UTC', expires `2021-03-17 16:40:46 UTC', pin-sha256=\"YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg=\"\n- Status: The certificate is NOT trusted. The certificate issuer is unknown. \n*** PKI verification of server certificate failed...\n- Description: (TLS1.3-X.509)-(ECDHE-SECP256R1)-(RSA-PSS-RSAE-SHA256)-(AES-256-GCM)\n- Options:\n- Handshake was completed\n\n- Simple Client Mode:\n\n")
  (apply tls--filter (#<process brause.cc> "Processed 0 CA certificate(s).\nResolving 'brause.cc:30832'...\nConnecting to '84.22.118.61:30832'...\n- Certificate type: X.509\n- Got a certificate list of 2 certificates.\n- Certificate[0] info:\n - subject `CN=brause.cc', issuer `CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US', serial 0x036e0cf8338636f52b6d0d93f76268279123, RSA key 4096 bits, signed using RSA-SHA256, activated `2020-06-01 00:01:57 UTC', expires `2020-08-30 00:01:57 UTC', pin-sha256=\"Rek9omuKhVeg6P+JHum2eyiiURpgd1lWrl1uzdyQBkY=\"\n\011Public Key ID:\n\011\011sha1:184ddb2a9480c77da34ebb43d542e634ec8e08b4\n\011\011sha256:45e93da26b8a8557a0e8ff891ee9b67b28a2511a60775956ae5d6ecddc900646\n\011Public Key PIN:\n\011\011pin-sha256:Rek9omuKhVeg6P+JHum2eyiiURpgd1lWrl1uzdyQBkY=\n\n- Certificate[1] info:\n - subject `CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US', issuer `CN=DST Root CA X3,O=Digital Signature Trust Co.', serial 0x0a0141420000015385736a0b85eca708, RSA key 2048 bits, signed using RSA-SHA256, activated `2016-03-17 16:40:46 UTC', expires `2021-03-17 16:40:46 UTC', pin-sha256=\"YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg=\"\n- Status: The certificate is NOT trusted. The certificate issuer is unknown. \n*** PKI verification of server certificate failed...\n- Description: (TLS1.3-X.509)-(ECDHE-SECP256R1)-(RSA-PSS-RSAE-SHA256)-(AES-256-GCM)\n- Options:\n- Handshake was completed\n\n- Simple Client Mode:\n\n"))
  (explain-pause--wrap-callback #s(explain-pause-command-record :command process-filter :native nil :parent #s(explain-pause-command-record :command "brause.cc" :native nil :parent #s(explain-pause-command-record :command my-irc :native nil :parent #s(explain-pause-command-record :command hydra-distractions/my-irc-and-exit :native nil :parent #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 3781 :entry-snap (24338 39546 539838 261000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) :executing-time 0 :entry-snap (24338 39546 538680 887000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 1) :executing-time 223 :entry-snap (24338 39546 315515 603000) :too-slow t :is-profiled nil :under-profile nil :profile nil :depth 2) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 3) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 4) tls--filter #<process brause.cc> "Processed 0 CA certificate(s).\nResolving 'brause.cc:30832'...\nConnecting to '84.22.118.61:30832'...\n- Certificate type: X.509\n- Got a certificate list of 2 certificates.\n- Certificate[0] info:\n - subject `CN=brause.cc', issuer `CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US', serial 0x036e0cf8338636f52b6d0d93f76268279123, RSA key 4096 bits, signed using RSA-SHA256, activated `2020-06-01 00:01:57 UTC', expires `2020-08-30 00:01:57 UTC', pin-sha256=\"Rek9omuKhVeg6P+JHum2eyiiURpgd1lWrl1uzdyQBkY=\"\n\011Public Key ID:\n\011\011sha1:184ddb2a9480c77da34ebb43d542e634ec8e08b4\n\011\011sha256:45e93da26b8a8557a0e8ff891ee9b67b28a2511a60775956ae5d6ecddc900646\n\011Public Key PIN:\n\011\011pin-sha256:Rek9omuKhVeg6P+JHum2eyiiURpgd1lWrl1uzdyQBkY=\n\n- Certificate[1] info:\n - subject `CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US', issuer `CN=DST Root CA X3,O=Digital Signature Trust Co.', serial 0x0a0141420000015385736a0b85eca708, RSA key 2048 bits, signed using RSA-SHA256, activated `2016-03-17 16:40:46 UTC', expires `2021-03-17 16:40:46 UTC', pin-sha256=\"YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg=\"\n- Status: The certificate is NOT trusted. The certificate issuer is unknown. \n*** PKI verification of server certificate failed...\n- Description: (TLS1.3-X.509)-(ECDHE-SECP256R1)-(RSA-PSS-RSAE-SHA256)-(AES-256-GCM)\n- Options:\n- Handshake was completed\n\n- Simple Client Mode:\n\n")
  (apply explain-pause--wrap-callback #s(explain-pause-command-record :command process-filter :native nil :parent #s(explain-pause-command-record :command "brause.cc" :native nil :parent #s(explain-pause-command-record :command my-irc :native nil :parent #s(explain-pause-command-record :command hydra-distractions/my-irc-and-exit :native nil :parent #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 3781 :entry-snap (24338 39546 539838 261000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) :executing-time 0 :entry-snap (24338 39546 538680 887000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 1) :executing-time 223 :entry-snap (24338 39546 315515 603000) :too-slow t :is-profiled nil :under-profile nil :profile nil :depth 2) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 3) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 4) tls--filter (#<process brause.cc> "Processed 0 CA certificate(s).\nResolving 'brause.cc:30832'...\nConnecting to '84.22.118.61:30832'...\n- Certificate type: X.509\n- Got a certificate list of 2 certificates.\n- Certificate[0] info:\n - subject `CN=brause.cc', issuer `CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US', serial 0x036e0cf8338636f52b6d0d93f76268279123, RSA key 4096 bits, signed using RSA-SHA256, activated `2020-06-01 00:01:57 UTC', expires `2020-08-30 00:01:57 UTC', pin-sha256=\"Rek9omuKhVeg6P+JHum2eyiiURpgd1lWrl1uzdyQBkY=\"\n\011Public Key ID:\n\011\011sha1:184ddb2a9480c77da34ebb43d542e634ec8e08b4\n\011\011sha256:45e93da26b8a8557a0e8ff891ee9b67b28a2511a60775956ae5d6ecddc900646\n\011Public Key PIN:\n\011\011pin-sha256:Rek9omuKhVeg6P+JHum2eyiiURpgd1lWrl1uzdyQBkY=\n\n- Certificate[1] info:\n - subject `CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US', issuer `CN=DST Root CA X3,O=Digital Signature Trust Co.', serial 0x0a0141420000015385736a0b85eca708, RSA key 2048 bits, signed using RSA-SHA256, activated `2016-03-17 16:40:46 UTC', expires `2021-03-17 16:40:46 UTC', pin-sha256=\"YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg=\"\n- Status: The certificate is NOT trusted. The certificate issuer is unknown. \n*** PKI verification of server certificate failed...\n- Description: (TLS1.3-X.509)-(ECDHE-SECP256R1)-(RSA-PSS-RSAE-SHA256)-(AES-256-GCM)\n- Options:\n- Handshake was completed\n\n- Simple Client Mode:\n\n"))
  (#f(compiled-function (&rest callback-args) #<bytecode 0x17135dd>) #<process brause.cc> "Processed 0 CA certificate(s).\nResolving 'brause.cc:30832'...\nConnecting to '84.22.118.61:30832'...\n- Certificate type: X.509\n- Got a certificate list of 2 certificates.\n- Certificate[0] info:\n - subject `CN=brause.cc', issuer `CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US', serial 0x036e0cf8338636f52b6d0d93f76268279123, RSA key 4096 bits, signed using RSA-SHA256, activated `2020-06-01 00:01:57 UTC', expires `2020-08-30 00:01:57 UTC', pin-sha256=\"Rek9omuKhVeg6P+JHum2eyiiURpgd1lWrl1uzdyQBkY=\"\n\011Public Key ID:\n\011\011sha1:184ddb2a9480c77da34ebb43d542e634ec8e08b4\n\011\011sha256:45e93da26b8a8557a0e8ff891ee9b67b28a2511a60775956ae5d6ecddc900646\n\011Public Key PIN:\n\011\011pin-sha256:Rek9omuKhVeg6P+JHum2eyiiURpgd1lWrl1uzdyQBkY=\n\n- Certificate[1] info:\n - subject `CN=Let's Encrypt Authority X3,O=Let's Encrypt,C=US', issuer `CN=DST Root CA X3,O=Digital Signature Trust Co.', serial 0x0a0141420000015385736a0b85eca708, RSA key 2048 bits, signed using RSA-SHA256, activated `2016-03-17 16:40:46 UTC', expires `2021-03-17 16:40:46 UTC', pin-sha256=\"YLh1dUR9y6Kja30RrAn7JKnbQG/uEtLMkBgFF2Fuihg=\"\n- Status: The certificate is NOT trusted. The certificate issuer is unknown. \n*** PKI verification of server certificate failed...\n- Description: (TLS1.3-X.509)-(ECDHE-SECP256R1)-(RSA-PSS-RSAE-SHA256)-(AES-256-GCM)\n- Options:\n- Handshake was completed\n\n- Simple Client Mode:\n\n")

Backtrace after reconnection attempt:

Debugger entered--Lisp error: (error "Unexpected event in tls sentinel: \"killed\n\"")
  (signal error ("Unexpected event in tls sentinel: \"killed\n\""))
  (error "Unexpected event in tls sentinel: %S" "killed\n")
  (tls--sentinel #<process brause.cc> "killed\n")
  (apply tls--sentinel (#<process brause.cc> "killed\n"))
  (explain-pause--wrap-callback #s(explain-pause-command-record :command process-sentinel :native nil :parent #s(explain-pause-command-record :command "brause.cc" :native nil :parent #s(explain-pause-command-record :command my-irc :native nil :parent #s(explain-pause-command-record :command hydra-distractions/my-irc-and-exit :native nil :parent #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 4431 :entry-snap (24338 39630 516136 634000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) :executing-time 0 :entry-snap (24338 39546 538680 887000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 1) :executing-time 223 :entry-snap (24338 39546 315515 603000) :too-slow t :is-profiled nil :under-profile nil :profile nil :depth 2) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 3) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 4) tls--sentinel #<process brause.cc> "killed\n")
  (apply explain-pause--wrap-callback #s(explain-pause-command-record :command process-sentinel :native nil :parent #s(explain-pause-command-record :command "brause.cc" :native nil :parent #s(explain-pause-command-record :command my-irc :native nil :parent #s(explain-pause-command-record :command hydra-distractions/my-irc-and-exit :native nil :parent #s(explain-pause-command-record :command root-emacs :native nil :parent nil :executing-time 4431 :entry-snap (24338 39630 516136 634000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 0) :executing-time 0 :entry-snap (24338 39546 538680 887000) :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 1) :executing-time 223 :entry-snap (24338 39546 315515 603000) :too-slow t :is-profiled nil :under-profile nil :profile nil :depth 2) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 3) :executing-time 0 :entry-snap nil :too-slow nil :is-profiled nil :under-profile nil :profile nil :depth 4) tls--sentinel (#<process brause.cc> "killed\n"))
  (#f(compiled-function (&rest callback-args) #<bytecode 0x17135a5>) #<process brause.cc> "killed\n")
  (delete-process #<process brause.cc>)
  (circe-reconnect--internal)
  (circe-reconnect)
  (#<subr funcall-interactively> circe-reconnect)
  (apply #<subr funcall-interactively> circe-reconnect)
  (funcall-interactively circe-reconnect)
  (#<subr call-interactively> circe-reconnect)
  (apply #<subr call-interactively> circe-reconnect)
  (explain-pause--wrap-call-interactively #<subr call-interactively> circe-reconnect)
  (apply explain-pause--wrap-call-interactively #<subr call-interactively> circe-reconnect)
  (call-interactively circe-reconnect)
  (circe-reconnect-all)
  (#<subr funcall-interactively> circe-reconnect-all)
  (apply #<subr funcall-interactively> circe-reconnect-all)
  (funcall-interactively circe-reconnect-all)
  (#<subr call-interactively> circe-reconnect-all record nil)
  (apply #<subr call-interactively> (circe-reconnect-all record nil))
  (explain-pause--wrap-call-interactively #<subr call-interactively> circe-reconnect-all record nil)
  (apply explain-pause--wrap-call-interactively #<subr call-interactively> (circe-reconnect-all record nil))
  (call-interactively circe-reconnect-all record nil)
  (command-execute circe-reconnect-all record)
  (let ((prefix-arg current-prefix-arg)) (command-execute command (quote record)) (smex-rank command))
  (progn (setq this-command command) (setq real-this-command command) (let ((prefix-arg current-prefix-arg)) (command-execute command (quote record)) (smex-rank command)))
  (if (commandp command) (progn (setq this-command command) (setq real-this-command command) (let ((prefix-arg current-prefix-arg)) (command-execute command (quote record)) (smex-rank command))))
  (helm-smex-execute-command circe-reconnect-all)
  (helm-execute-selection-action-1)
  (helm-execute-selection-action)
  (helm-internal helm-smex-source nil nil nil nil "*helm-smex*" nil nil nil)
  (apply helm-internal (helm-smex-source nil nil nil nil "*helm-smex*" nil nil nil))
  (helm helm-smex-source nil nil nil nil "*helm-smex*" nil nil nil)
  (apply helm (helm-smex-source nil nil nil nil "*helm-smex*" nil nil nil))
  (helm :sources helm-smex-source :buffer "*helm-smex*")
  (helm-smex)
  (#<subr funcall-interactively> helm-smex)
  (apply #<subr funcall-interactively> helm-smex)
  (funcall-interactively helm-smex)
  (#<subr call-interactively> helm-smex nil nil)
  (apply #<subr call-interactively> (helm-smex nil nil))
  (explain-pause--wrap-call-interactively #<subr call-interactively> helm-smex nil nil)
  (apply explain-pause--wrap-call-interactively #<subr call-interactively> (helm-smex nil nil))
  (call-interactively helm-smex nil nil)
  (command-execute helm-smex)

[lastquestion]

Oh, I see. It's good circe has it's source code on GH ;)

In tls-filter there's a call to set-process-plist https://github.com/jorgenschaefer/circe/blob/master/make-tls-process.el#L160 which replaces the process's plist with the argument given, but explain-pause-mode has also stored its own data in that plist. So that is stomping the data explain-pause-mode keeps to keep track of the command parent of the filter.

Reduced repro is like

  (setq proc (make-process
              :name "test"
              :buffer "test"
              :command '("cat")
              :filter 'my-filter))

  (set-process-plist proc nil)

Thanks, let me fix this bug first, then the other bug you reported, 🙂

[lastquestion]

I think I'm going to advise set-process-plist so that the various explain-pause-* plist values are never lost.

set-process-plist is never called from C code, so this feels safe.

An alternate approach would to have a hashmap and key every process into the hashmap, but then I have to do record keeping on the hash map, and delete entries when processes end, and it's not O(1) always, only on average.

So I think advising is probably the easiest and cleanest way to fix this.

[lastquestion]

^- should be fixed now, give HEAD a try @wasamasa thanks ❤️

[wasamasa]

Thanks, that fixed it.