Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Gustavo Barros]

Hi All,

The marking of repeated tasks as "done" is currently resulting in 
duplicate entries in the "LOGBOOK" drawer, which is not expected.  I 
don't know exactly when this came to be, but it does not happen in the 
current built-in version (9.4.4), while it does in the latest release 
(9.4.6).

An ECM to reproduce the issue is the following.

Start 'emacs -Q' and do an initial setup:

#+begin_src emacs-lisp
(add-to-list 'load-path "~/.emacs.d/elpa/org-9.4.6")
(setq org-log-into-drawer t)
(setq org-log-done 'time)
(setq org-todo-keywords
      '((sequence "TODO(t)" "SOMEDAY(s)" "|" "DONE(d!)")
        (sequence "NEXT(n)" "WAIT(w@/!)" "|" "CANCELED(c@/!)")))
#+end_src

Visit file =test.org= with contents:
#+begin_src org
,* TODO Foo
SCHEDULED: <2021-06-13 Sun +1d>
#+end_src

Now call "C-c C-t" (`org-todo'), and call the key "d" for "DONE", as per 
the above settings.  The resulting buffer is:

#+begin_src org
,* TODO Foo
SCHEDULED: <2021-06-15 Tue +1d>
:PROPERTIES:
:LAST_REPEAT: [2021-06-14 Mon 10:27]
:END:
:LOGBOOK:
- State "DONE"       from "TODO"       [2021-06-14 Mon 10:27]
- State "DONE"       from "TODO"       [2021-06-14 Mon 10:27]
:END:
#+end_src


Best regards,
Gustavo.



Emacs  : GNU Emacs 27.2 (build 1, x86_64-pc-linux-gnu, GTK+ Version 
3.24.20, cairo version 1.16.0)
 of 2021-03-25
Package: Org mode version 9.4.6 (9.4.6-gab9f2a @ 
/home/gustavo/.emacs.d/elpa/org-9.4.6/)

current state:
==============
(setq
 org-src-mode-hook '(org-src-babel-configure-edit-buffer
		     org-src-mode-configure-edit-buffer)
 org-link-shell-confirm-function 'yes-or-no-p
 org-metadown-hook '(org-babel-pop-to-session-maybe)
 org-clock-out-hook '(org-clock-remove-empty-clock-drawer)
 org-mode-hook '(#[0 "\300\301\302\303\304$\207"
		   [add-hook change-major-mode-hook org-show-all append 
		   local]
		   5]
		 #[0 "\300\301\302\303\304$\207"
		   [add-hook change-major-mode-hook 
		   org-babel-show-result-all
		    append local]
		   5]
		 org-babel-result-hide-spec org-babel-hide-all-hashes)
 org-archive-hook '(org-attach-archive-delete-maybe)
 org-confirm-elisp-link-function 'yes-or-no-p
 org-agenda-before-write-hook '(org-agenda-add-entry-text)
 org-metaup-hook '(org-babel-load-in-session-maybe)
 org-bibtex-headline-format-function #[257 "\300\236A\207" [:title] 3 
 "\n\n(fn ENTRY)"]
 org-babel-pre-tangle-hook '(save-buffer)
 org-tab-first-hook '(org-babel-hide-result-toggle-maybe
		      org-babel-header-arg-expand)
 org-log-done 'time
 org-agenda-loop-over-headlines-in-active-region nil
 org-occur-hook '(org-first-headline-recenter)
 org-log-into-drawer t
 org-cycle-hook '(org-cycle-hide-archived-subtrees 
 org-cycle-hide-drawers
		  org-cycle-show-empty-lines
		  org-optimize-window-after-visibility-change)
 org-todo-keywords '((sequence "TODO(t)" "SOMEDAY(s)" "|" "DONE(d!)")
		     (sequence "NEXT(n)" "WAIT(w@/!)" "|" 
		     "CANCELED(c@/!)"))
 org-speed-command-hook '(org-speed-command-activate
			  org-babel-speed-command-activate)
 org-export-before-parsing-hook '(org-attach-expand-links)
 org-confirm-shell-link-function 'yes-or-no-p
 org-link-parameters '(("attachment" :follow org-attach-follow :complete
			org-attach-complete-link)
		       ("id" :follow org-id-open)
		       ("eww" :follow org-eww-open :store 
		       org-eww-store-link)
		       ("rmail" :follow org-rmail-open :store
			org-rmail-store-link)
		       ("mhe" :follow org-mhe-open :store 
		       org-mhe-store-link)
		       ("irc" :follow org-irc-visit :store 
		       org-irc-store-link
			:export org-irc-export)
		       ("info" :follow org-info-open :export 
		       org-info-export
			:store org-info-store-link)
		       ("gnus" :follow org-gnus-open :store
			org-gnus-store-link)
		       ("docview" :follow org-docview-open :export
			org-docview-export :store 
			org-docview-store-link)
		       ("bibtex" :follow org-bibtex-open :store
			org-bibtex-store-link)
		       ("bbdb" :follow org-bbdb-open :export 
		       org-bbdb-export
			:complete org-bbdb-complete-link :store
			org-bbdb-store-link)
		       ("w3m" :store org-w3m-store-link) ("file+sys")
		       ("file+emacs") ("shell" :follow 
		       org-link--open-shell)
		       ("news" :follow
			#[514 "\301\300\302Q\"\207"
			  ["news" browse-url ":"] 6 "\n\n(fn URL ARG)"]
			)
		       ("mailto" :follow
			#[514 "\301\300\302Q\"\207"
			  ["mailto" browse-url ":"] 6 "\n\n(fn URL 
			  ARG)"]
			)
		       ("https" :follow
			#[514 "\301\300\302Q\"\207"
			  ["https" browse-url ":"] 6 "\n\n(fn URL ARG)"]
			)
		       ("http" :follow
			#[514 "\301\300\302Q\"\207"
			  ["http" browse-url ":"] 6 "\n\n(fn URL ARG)"]
			)
		       ("ftp" :follow
			#[514 "\301\300\302Q\"\207" ["ftp" browse-url 
                         ":"]
			  6 "\n\n(fn URL ARG)"]
			)
		       ("help" :follow org-link--open-help)
		       ("file" :complete org-link-complete-file)
		       ("elisp" :follow org-link--open-elisp)
		       ("doi" :follow org-link--open-doi))
 org-link-elisp-confirm-function 'yes-or-no-p
 )

Re: Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Bhavin Gandhi]

On Mon, 14 Jun 2021 at 19:10, Gustavo Barros wrote:
> The marking of repeated tasks as "done" is currently resulting in
> duplicate entries in the "LOGBOOK" drawer, which is not expected.  I
> don't know exactly when this came to be, but it does not happen in the
> current built-in version (9.4.4), while it does in the latest release
> (9.4.6).

I was able to reproduce this, and here are my findings as well as a
reproducible configuration with only a few settings.

=test.org= file:

#+begin_src org
* TODO First

* TODO Read book
SCHEDULED: <2021-06-15 Tue +1d>
#+end_src

Start emacs -Q and open the test.org file.

Go to the 'First' entry, and do C-c C-t. This adds an a timestamp record
(this does not happen with 9.4.4, not sure if the default behavior has
been changed).

Changed test.org file:

#+begin_src org
* DONE First

- State "DONE"       from "TODO"       [2021-06-14 Mon 23:23]
* TODO Read book
SCHEDULED: <2021-06-15 Tue +1d>
#+end_src

Now, load this configuration:

#+begin_src elisp
(add-to-list 'load-path "~/src/org-mode/lisp/")

(setq org-todo-keywords
      '((sequence "TODO(t)" "|" "DONE(d!)")))
#+end_src

Open the test.org again, and go to the "Read book" entry, mark it done
with C-c C-t. Now, there are two timestamp changes getting recorded.

#+begin_src org
[…]
* TODO Read book
SCHEDULED: <2021-06-16 Wed +1d>
:PROPERTIES:
:LAST_REPEAT: [2021-06-14 Mon 23:26]
:END:
- State "DONE"       from "TODO"       [2021-06-14 Mon 23:26]
- State "DONE"       from "TODO"       [2021-06-14 Mon 23:26]
#+end_src

-- 
Bhavin Gandhi (bhavin192) | https://geeksocket.in

Re: Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Gustavo Barros]

Hi Bhavin,

On Mon, 14 Jun 2021 at 15:01, Bhavin Gandhi <bhavin7392@gmail.com> 
wrote:

> On Mon, 14 Jun 2021 at 19:10, Gustavo Barros wrote:
>> The marking of repeated tasks as "done" is currently resulting in
>> duplicate entries in the "LOGBOOK" drawer, which is not expected.  I
>> don't know exactly when this came to be, but it does not happen in 
>> the
>> current built-in version (9.4.4), while it does in the latest release
>> (9.4.6).
>
> I was able to reproduce this, and here are my findings as well as a
> reproducible configuration with only a few settings.

Thank you for taking the time to try this out and for confirming you are 
able to reproduce the issue.

(I'm marking this bug confirmed.  I'd normally refrain from "self 
confirming" but, since Bhavin was able to reproduce and I consider this 
one to be particularly relevant, I made an exception.)

Best regards,
Gustavo.

Re: Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Jeff Kowalski]

[-- Attachment #1: Type: text/plain, Size: 563 bytes --]

I can confirm the same is happening here for me with Org mode version 9.4.6
(9.4.6-4-g093c94-elpa @ /home/jeff/.emacs.d/elpa/org-20210607/) on GNU
Emacs 28.0.50 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.20, cairo
version 1.16.0) of 2021-06-16
The duplicate LOGBOOK entries also seem to be messing up the graphical
display of habit records in the agenda.  Deleting the duplicates returns
the habit display to expected output.  I'd be happy to share details of
that symptom, but the root cause seems to clearly be the duplicates in the
LOGBOOK
Jeff Kowalski

[-- Attachment #2: Type: text/html, Size: 613 bytes --]

Re: Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Gustavo Barros]

Hi Jeff,

On Wed, 16 Jun 2021 at 23:22, Jeff Kowalski <jeff.kowalski@gmail.com> 
wrote:

> I can confirm the same is happening here for me with Org mode version 
> 9.4.6
> (9.4.6-4-g093c94-elpa @ /home/jeff/.emacs.d/elpa/org-20210607/) on GNU
> Emacs 28.0.50 (build 1, x86_64-pc-linux-gnu, GTK+ Version 3.24.20, 
> cairo
> version 1.16.0) of 2021-06-16
> The duplicate LOGBOOK entries also seem to be messing up the graphical
> display of habit records in the agenda.  Deleting the duplicates 
> returns
> the habit display to expected output.  I'd be happy to share details 
> of
> that symptom, but the root cause seems to clearly be the duplicates in 
> the
> LOGBOOK

Thanks for confirming and for the habits info.  So that's what was 
happening with my consistency graphs.  I had indeed been noticing they 
felt "off", but I eventually reverted to 9.4.4 because of the duplicate 
entries and forgot about it.  It seems then that this got solved for me 
not by the reverting itself but by me removing the duplicate entries in 
the LOGBOOK.

Would clocking reports be affected too? (I'm not personally an user of 
clocking, so I don't really know).

Perhaps a "lint" for LOGBOOK duplicates would be a good idea alongside 
with the fix, so that people could go about fixing their data with a 
little more convenience?

Best regards,
Gustavo.

Re: Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Jeff Kowalski]

[-- Attachment #1: Type: text/plain, Size: 3637 bytes --]

While I don't have a fix for the root issue, I did have a chance to create
a lint for LOGBOOK duplicates, as you suggested.
It can be found here:
https://github.com/jeffkowalski/prelude/commit/f44b6041730469ba2094849b60d301cd94a5bed1#diff-3de035eea502a119bcdd40f4adc3d6108d4f337f827358cb2361623525682042R1199-R1251

Also below:

  (defun jeff/org-logbook-retrieve-timestamps (beg end)
    "Retrieve timestamp of all state-change entries between BEG and END."
    (save-excursion
      (let* ((reversed org-log-states-order-reversed)
             (search (if reversed 're-search-forward 're-search-backward))
             (limit (if reversed end (point)))
             (re (format
                  "^[ \t]*-[ \t]+\\(?:State \"%s\"\s+from\s+\"%s\".*%s%s\\)"
                  org-todo-regexp
                  org-todo-regexp
                  org-ts-regexp-inactive
                  (let ((value (cdr (assq 'done org-log-note-headings))))
                    (if (not value) ""
                      (concat "\\|"
                              (org-replace-escapes
                               (regexp-quote value)
                               `(("%d" . ,org-ts-regexp-inactive)
                                 ("%D" . ,org-ts-regexp)
                                 ("%s" . "\"\\S-+\"")
                                 ("%S" . "\"\\S-+\"")
                                 ("%t" . ,org-ts-regexp-inactive)
                                 ("%T" . ,org-ts-regexp)
                                 ("%u" . ".*?")
                                 ("%U" . ".*?"))))))))
             log-entries)
        (goto-char (if reversed beg end))
        (while (funcall search re limit t)
          (push (match-string-no-properties 3) log-entries))
        log-entries)))

  (defun org-lint-duplicate-logbook-timestamps (ast)
    "Report LOGBOOK entries with duplicate timestamp"
    (org-element-map ast 'drawer
      (lambda (d)
        (when (equal (org-element-property :drawer-name d) "LOGBOOK")
          (let* ((beg (org-element-property :contents-begin d))
                 (end (org-element-property :contents-end d))
                 (orig (jeff/org-logbook-retrieve-timestamps beg end))
                 (uniq (cl-remove-duplicates
                        orig
                        :test (lambda (x y) (or (null y) (equal x y)))
                        :from-end t))
                 (diff (- (length orig) (length uniq))))
            (unless (zerop diff)
              (list (org-element-property :begin d)
                    (format "LOGBOOK has %d entries with duplicate
timestamp" diff))))))))

  (add-to-list 'org-lint--checkers
               (make-org-lint-checker
                :name 'duplicate-logbook-timestamps
                :description "Report LOGBOOK entries with duplicate
timestamp"
                :categories '(properties)))


On Thu, Jun 17, 2021 at 6:16 AM Gustavo Barros <gusbrs.2016@gmail.com>
wrote:

> Thanks for confirming and for the habits info.  So that's what was
> happening with my consistency graphs.  I had indeed been noticing they
> felt "off", but I eventually reverted to 9.4.4 because of the duplicate
> entries and forgot about it.  It seems then that this got solved for me
> not by the reverting itself but by me removing the duplicate entries in
> the LOGBOOK.
>
> Would clocking reports be affected too? (I'm not personally an user of
> clocking, so I don't really know).
>
> Perhaps a "lint" for LOGBOOK duplicates would be a good idea alongside
> with the fix, so that people could go about fixing their data with a
> little more convenience?
>
> Best regards,
> Gustavo.
>

[-- Attachment #2: Type: text/html, Size: 5157 bytes --]

Re: Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Gustavo Barros]

Hi Jeff,

On Sat, 26 Jun 2021 at 00:13, Jeff Kowalski <jeff.kowalski@gmail.com> 
wrote:

> While I don't have a fix for the root issue, I did have a chance to 
> create
> a lint for LOGBOOK duplicates, as you suggested.
> It can be found here:

Looks good!

Thank you very much.

Best regards,
Gustavo.

Re: Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Gustavo Barros]

Hi All,

On Sat, 26 Jun 2021 at 00:13, Jeff Kowalski <jeff.kowalski@gmail.com> 
wrote:

> While I don't have a fix for the root issue, I did have a chance to 
> create
> a lint for LOGBOOK duplicates, as you suggested.

Since Jeff put some effort, I went for some too.  :-)

I did some digging and, as far as I can tell, the commit which 
introduces the bug is "c670379ad Fix `org-agenda-todo' undo behavior 
when logging (not adding note)".

I tested the ECM initially reported, and I don't find the behavior in 
commit `b2be3dd0e', but I do find it in `59edcc27c', and what happened 
in `master' between the two is `c670379ad'.

Not a fix, but this should narrow the search down.

Best regards,
Gustavo.

Re: Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Bhavin Gandhi]

On Sat, 26 Jun 2021 at 00:13, Jeff Kowalski wrote:
> While I don't have a fix for the root issue, I did have a chance to
> create
> a lint for LOGBOOK duplicates, as you suggested.

Thank you Jeff, I had no clue how to write something like that :)

On Sun, 27 Jun 2021 at 07:58, Gustavo Barros wrote:
>
> I did some digging and, as far as I can tell, the commit which
> introduces the bug is "c670379ad Fix `org-agenda-todo' undo behavior
> when logging (not adding note)".
>
> I tested the ECM initially reported, and I don't find the behavior in
> commit `b2be3dd0e', but I do find it in `59edcc27c', and what happened
> in `master' between the two is `c670379ad'.

You are right, I actually did a bisect last week and found that change
has introduced this behavior. I should have posted that immediately, it
would have saved some of your time. I'm trying to wrap my head around
the `org-todo' code as well as the change from `c670379ad'.

Till now I found that the function `org-add-log-setup' is getting
called twice. Why that's happening, I'm not sure yet. I think running
edebug will help here, I'm going to try that.

-- 
Bhavin Gandhi (bhavin192) | https://geeksocket.in

Re: Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Gustavo Barros]

On Sun, 27 Jun 2021 at 03:31, Bhavin Gandhi <bhavin7392@gmail.com> 
wrote:

> You are right, I actually did a bisect last week and found that change
> has introduced this behavior. I should have posted that immediately, 
> it
> would have saved some of your time.

No problem.  Thanks for confirming you reached the same conclusion.

Best,
Gustavo.

Re: Bug: Duplicate logbook entry for repeated tasks [9.4.6 (9.4.6-gab9f2a @ /home/gustavo/.emacs.d/elpa/org-9.4.6/)]

[Bhavin Gandhi]

On Sun, 27 Jun 2021 at 12:01, Bhavin Gandhi wrote:
>
> Till now I found that the function `org-add-log-setup' is getting
> called twice. Why that's happening, I'm not sure yet. I think running
> edebug will help here, I'm going to try that.
>

I found the reason for this behavior with the help of edebug.

`org-todo' calls `org-add-log-setup' to log the state change, and then
it calls `org-auto-repeat-maybe'.

The `org-auto-repeat-maybe' then calls the `org-add-log-setup' again, I
think this is for logging something related to repeated entries.

Before the change `c670379ad', `org-add-log-setup' used to add
`org-add-log-note' to post-command-hook instead of calling it directly.

If I have understood the post-command-hooks correctly, it used to keep
only one entry of `org-add-log-note'. This is because `add-hook' function
makes sure that there are no duplicate entries in the hooks.

I'm not sure how this can be fixed, I'm going to read the
`org-auto-repeat-maybe' to understand what all it is doing.