Unpredictable bug: "NewHeadline" instead of actual headline

[SegundoBob]

Leo-Editor Version:

Leo 6.1-devel, devel branch, build f5986d8016
2019-08-09 10:23:41 -0500
Python 3.6.8, PyQt version 5.11.1

Bug Description:

This bug may be in my code or in Leo-Editor code.  I have been seeing occurrences for at least two weeks.

The bug occurs when I run my unit tests for my program that compares two Leo-Editor files.  I have 41 unit tests.  The bug occurs about once every 30 tests.

My comparison program uses LeoBridge to access Leo-Editor files.  File "Content" as accessed by vnode (not position).  File "structure" is analyzed by position (path).  That is, my program gets the headline and body from the vnode (vn.h, bn.b).  When my comparison program compares the unit test File A and File B, the bug never occurs.  Using LeoBridge my comparision program produces a difference file (File D).  The unit tests use subprocess.call() to execute my comparision program, so the process comparing File A and File B and producing File D ends.  Then the unit tests use subprocess.call() to compare the actual File D with the expected File D.  This is when the bug occurs.

The bug is always that a headline in File D, is seen to be "NewHeadline."  But when I look at File D, there is no "NewHeadline" and File D is exactly as expected.

There are never two or more bug occurrences in comparing one File D.  The bug never occurs on a node body.  There is a slight tendency for bug occurrences to cluster.  That is, sometimes it occurs on two tests in a row or even three tests in row.

Help:

Does anyone have any ideas about how this bug could occur?  Does anyone have any ideas about how to chase this bug?

[Brian Theado]

Without seeing actual code, I find it difficult to understand your explanation enough to come up with any guess. But it seems you have 3 things: leo code, your comparison code, and your unit test code. Since this problem started happening, at least one of those things had to have changed right? I see you are running a git commit from a month ago, so maybe your leo code hasn't changed since the problem appeared and so it must be your unit test or program code? Do you have a history (in git or something) of your code? When it is a problem which is fairly easy to reliably reproduce then git bisect is very handy.

It isn't clear from your description what your 2nd subprocess.call is executing. Whatever it is, maybe you can have extra tracing or set a debugger breakpoint whenever newHeadline is seen and that way you can get more information.

--
You received this message because you are subscribed to the Google Groups "leo-editor" group.
To unsubscribe from this group and stop receiving emails from it, send an email to leo-editor+...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/leo-editor/fd49a5e7-6694-4bf6-9b22-88c517ef38ef%40googlegroups.com.

[SegundoBob]

On 9/19/19 5:22 PM, Brian Theado wrote:

> It isn't clear from your description what your 2nd subprocess.call is executing.

The second subprocess.call() executes my compare Leo-Editor files program.  This is the same program executed by my first subprocess.call().

Thanks for your suggestions.

Segundo Bob

[vitalije]

Can you share your code for the second process that compares outlines D and expected D. I don't know how you go through the nodes of these two files. A phantom node that can't be seen might be a node which is not properly connected. Every vnode has to be linked to its parent i.e. its parent node must be in v.parents, and also for every parent in v.parents, must be v in parent.children. If your code for traversing outline nodes uses values from c.fileCommands.gnxDict, it might find some nodes that are not part of the outline. Such nodes are not visible in the outline.

Without looking at actual code I can't think of anything else.

Vitalije

[Edward K. Ream]

On Thursday, September 19, 2019 at 5:02:54 PM UTC-5, SegundoBob wrote:

This bug may be in my code or in Leo-Editor code.  I have been seeing occurrences for at least two weeks.

The bug occurs when I run my unit tests for my program that compares two Leo-Editor files.  I have 41 unit tests.  The bug occurs about once every 30 tests.

Sounds like a worthy bug.  Thanks for sharing it with us.

I don't have any ideas about causes.  My strategy would be to insert traces in Leo as follows:

I would trace fast.readFile in leoFileCommands.py.  This is the code that reads .leo files.

If your .leo files contain external files, I would also trace fast_at.scan_lines in leoAtFile.py.

My goal would be to have the traces fire only in unexpected situations, so I don't get overwhelmed with data.  If you can get that to happen you will likely have a handle on what is going on.

Edward

[SegundoBob]

On Thursday, September 19, 2019 at 10:41:46 PM UTC-7, vitalije wrote:

I don't know how you go through the nodes of these two files.

I obtain all the vnodes by doing a depth first walk starting at cmdr.hiddenRootNode.  The attribute vnode.children gives me the children of each vnode.  I use cmdr.clearAllVisited() and vnode.isVisited() to prevent visiting cloned sub-trees twice.  I believe Edward suggested more or less this strategy a long time ago.

I have also used emacs to examine the Leo-Editor files suffering from phantom "NewHeadline" and these files did not contain any "NewHeadline" and they contained only what I expected.  The files are small.

Thanks for the suggestion.  I hadn't considered phantom vnodes.  Have you in fact ever seen a phantom vnode?  I have not.

SegundoBob

[SegundoBob]

On Friday, September 20, 2019 at 3:33:31 AM UTC-7, Edward K. Ream wrote:

 

If your .leo files contain external files, I would also trace fast_at.scan_lines in leoAtFile.py.

The problem files are small and they do not contain any external files.

Thanks for your suggestions. I'll continue investigating.

SegundoBob

[vitalije]

  Have you in fact ever seen a phantom vnode?  I have not.

SegundoBob

From time to time I bump on something like this, mostly because I tend to search for nodes using c.fileCommands.gnxDict, or when I manually build subtree and forget to  create two way binding between children and parents.

Have you tried to disable plugins when loading leoBridge?

Vitalije

[Edward K. Ream]

On Friday, September 20, 2019 at 5:33:31 AM UTC-5, Edward K. Ream wrote:

Sounds like a worthy bug.  Thanks for sharing it with us.

A few more thoughts.

1. A good goal would be to drop into the debugger (g.pdb) when the bug happens. Easier said than done, surely.

If you can do this, then you can look around at the whole environment.  I suggest using g.printObj(x) on complex x.

2. I wonder whether this bug could be related to #35, which was the result of timing issues when opening multiple .leo files from the bridge. The fix is ugly enough that it might not be solid.

Edward

[SegundoBob]

On Sunday, September 22, 2019 at 2:12:03 AM UTC-7, Edward K. Ream wrote:

On Friday, September 20, 2019 at 5:33:31 AM UTC-5, Edward K. Ream wrote:

Sounds like a worthy bug.  Thanks for sharing it with us.

A few more thoughts.

I spent yesterday trying to put together a small test program and bug report concerning this bug.  I regret to say that the "Phantom NewHeadline" symptom appears to be the wrong symptom to investigate.  It appears that LeoBridge has very serious problems creating and/or changing a Leo-Editor file.  Almost everything I tried failed in some way every time.  I was seriously hampered by your decision not to fix issue #658, which prevented me from writing simple tests.  Not being able to close a LeoBridge commander is a very inconvenient restriction.  It would also help if there was a LeoBridge.close() method. 

[vitalije]

To avoid triggering #658, manually reopen g.app.db object after closing the first commander. Perhaps leoBridge.openLeoFile method could be modified to check if g.app.db is closed and if so, reopen it automatically. 

# add an import statement
import leo.core.leoCache as leoCache

# and then after closing first commander
cmdr1.close()
# insert the following two lines

bridge.g.app.global_cacher = leoCache.GlobalCacher()

bridge.g.app.db = bridge.g.app.global_cacher.db
# now you can open another file
cmdr2 = bridge.openLeoFile(...)

#

Vitalije

 

[SegundoBob]

I spoke too soon.  All the easy symptoms turned out to be bugs in my test programs.  No surprise there.

I'm back to trying to produce the "Phantom Headline" symptom, and unfortunately Vitalije's work around doesn't work.  It does get me through the second Leo-Editor file open, but then it fails with the "closed database" error on the second cmdr.save().

phantom_new_Headline_01_passes.py is a test that passes.   Using Vitalije's work around, I made it closer to my unit test that encounters the "Phantom Headline" symptom:  phantom_new_Headline_02_work_around_fails.py

Run of phantom_new_Headline_02_work_around_fails.py:

2019-09-22 15:56:08 /pri/git/leo_bug_demos/2019-09-21-Phantom-NewHeadline
$ ./test02.py
ic| test02.py:62 in main()
    cmdrT: Commander 139729630728768: '/pri/git/leo_bug_demos/2019-09-21-Phantom-NewHeadline/test.leo'
ic| test02.py:62 in main()
    cmdrT: Commander 139729631145264: '/pri/git/leo_bug_demos/2019-09-21-Phantom-NewHeadline/test.leo'
Traceback (most recent call last):
  File "./test02.py", line 172, in <module>
    main()
  File "./test02.py", line 63, in main
    cmdrT.save()
  File "/pri/git/leo-editor/leo/commands/commanderFileCommands.py", line 355, in save
    c.fileCommands.save(c.mFileName)
  File "/pri/git/leo-editor/leo/core/leoFileCommands.py", line 1049, in save
    g.app.commander_cacher.save(c, fileName, changeName=True)
  File "/pri/git/leo-editor/leo/core/leoCache.py", line 99, in save
    self.commit()
  File "/pri/git/leo-editor/leo/core/leoCache.py", line 58, in commit
    self.db.conn.commit()
sqlite3.ProgrammingError: Cannot operate on a closed database.

[vitalije]

O.k. just add two more lines:

bridge.g.app.commander_cacher = leoCache.CommanderCacher()

bridge.g.app.commander_db = bridge.g.app.commander_cacher.db

HTH Vitalije

[SegundoBob]

I think the bug is in Leo-Editor

test03 produces the same bug symptom as my unit tests of my compare Leo-Editor files:

"NewHeadline" is seen by LeoBridge but the disk file is correct and does not contain "NewHeadline".

For test03 errors/loops is larger, but the errors are still unpredictable with many error free loops.  For example.

31 loops 18 errors 58% errors/loops

51 loops 32 errors 62% errors/loops

Based on the above evidence, I think the bug is in Leo-Editor.

You can find the three Python files composing test03  here test03

Bug Symptoms

Each of the following should not be:

The root node has two parents.  Both parents are the hidden root node.  Ordinarily, the root node has exactly one parent.

The root node is the only node and its headline is "NewHeadline".

Note: I believe that Leo-Editor until recently set new node headlines to "NewHeadline", but now in most cases Leo-Editor sets new node headlines to "newHeadline" (no capital letter).

Test run breaking on the first error (test03 modified slightly since this run, to exit gracefully and to conditionally insert breakpoints)

2019-09-23 14:55:24 /pri/git/leo_bug_demos/2019-09-21-Phantom-NewHeadline
$ ./test03.py
Leo 6.1-devel, devel branch, build 53cf6d1bb1
2019-09-23 10:35:13 -0500

Expected:
0 Headline
0.0 Headline
0.0.0 Headline
0.1 Headline
0.2 Headline
0.2.0 Headline
Actual:
NewHeadline
> /pri/git/leo_bug_demos/2019-09-21-Phantom-NewHeadline/check_file.py(117)checkOutline()
-> exit(50)
(Pdb) where
  /pri/git/leo_bug_demos/2019-09-21-Phantom-NewHeadline/check_file.py(121)<module>()
-> main()
  /pri/git/leo_bug_demos/2019-09-21-Phantom-NewHeadline/check_file.py(56)main()
-> checkOutline(cmdrT, outline)
> /pri/git/leo_bug_demos/2019-09-21-Phantom-NewHeadline/check_file.py(117)checkOutline()
-> exit(50)
(Pdb) l
112                  print(hdr)
113              print('Actual:')
114              for hdr in walkList:
115                  print(hdr)
116              import pdb; pdb.set_trace()
117  ->            exit(50)
118      #@-others
119     
120      if __name__ == "__main__":
121          main()
122      #@-leo
(Pdb) walkList
['NewHeadline']
(Pdb) root
<pos 140033515115520 childIndex: 0 lvl: 0 key: 140033515118376:0 NewHeadline>
(Pdb) root.v
<VNode bob.20190923145528.2 NewHeadline>
(Pdb) root.v.parents
[<VNode hidden-root-vnode-gnx <hidden root vnode>>, <VNode hidden-root-vnode-gnx <hidden root vnode>>]
(Pdb) root.v.children
[]
(Pdb) root.v.parents[0]
<VNode hidden-root-vnode-gnx <hidden root vnode>>
(Pdb) root.v.parents[0].children
[<VNode bob.20190923145528.2 NewHeadline>]
(Pdb) cmdrT
Commander 140033515115464: '/pri/git/leo_bug_demos/2019-09-21-Phantom-NewHeadline/test.leo'
(Pdb)

[vitalije]

SegundoBob, it seems that google has stripped your attached files. Clicking in the link test03 does nothing.

You can find the three Python files composing test03  here test03

Can you post them in github or directly to my email: vitalijem (at) gmail dot (ending as usual).

Vitalije

[Edward K. Ream]

On Mon, Sep 23, 2019 at 5:56 PM SegundoBob <segun...@gmail.com> wrote:

I think the bug is in Leo-Editor

Please file a new issue.

Edward

[Edward K. Ream]

In the new issue, please pretend I know nothing of the old issue and its long history.  That is, please summarize the what is know as succinctly as you can.

It will also help me if you could edit the first comment as new data or ideas become available.  That way I won't have to wade through new batches of comments.

Edward

[vitalije]

SegundoBob, when I change in the test03.py script:

# leoPfn = pathlib.Path('test.leo')
# to
leoPfn = pathlib.Path('test.db')

There is no error reported with the phantom NewHeadline. However, every 4-5 seconds Leo reports a gnx clash. The next thing I am going to look for potential places where gnx clash can affect reading .leo xml file. 

Vitalije

[vitalije]

As I wrote in the #1348 it is my belief that this issue is caused by operating system itself. It seems that subprocess.call returns before process has fully finished and its file operations are actually flushed to disk. In this test script the next process sometimes starts before the previous one has finished.

Vitalije