Only first update of Form works, all others fail

[tracformsTrachacks@…]

Hi There!

I am trying to use TracForms 0.4.1-r10799 on trac 0.12.2 on an Ubuntu Lucid (10.4.2) Installation with python-2.6.5 and Genshi-6.1 (what else do you need?).

My problem is now, whenever I create a form and use it from the users point of view, the first modification succeeds perfectly. But when I try to modify the form again (eg. unset a checkbox) the command fails with "not enough arguments for format string". This is what is written in the log about that:

2011-10-19 13:38:39,471 Trac[api] DEBUG: UPDATE ARGS:{'__backpath__':
 u'/admintrac/wiki', '__FORM_TOKEN': u'cdfe1a1440e3758e59cf2df8',
 '__track_fields__': u'yes', '__basever__': u'1319023921', '__context__':
 u'["wiki","WikiStart",""]'}

This Problem does not occur, whenever I modify a text-field, it only happens with checkboxes.

salute

Jan

[Steffen Hoffmann]

Replying to tracformsTrachacks@mailfoo.doenerbier.de:

Hi There!

I am trying to use TracForms 0.4.1-r10799 on trac 0.12.2 on an Ubuntu Lucid (10.4.2) Installation with python-2.6.5 and Genshi-6.1 (what else do you need?).

Nothing, should be fine.

My problem is now, whenever I create a form and use it from the users point of view, the first modification succeeds perfectly. But when I try to modify the form again (eg. unset a checkbox) the command fails with "not enough arguments for format string".

Did you try to get advise on the mailing list (th-users) first? That's preferred, since this is a development tracking system.

This is what is written in the log about that:

2011-10-19 13:38:39,471 Trac[api] DEBUG: UPDATE ARGS:{'__backpath__': u'/admintrac/wiki', '__FORM_TOKEN': u'cdfe1a1440e3758e59cf2df8', '__track_fields__': u'yes', '__basever__': u'1319023921', '__context__': u'["wiki","WikiStart",""]'}

This Problem does not occur, whenever I modify a text-field, it only happens with checkboxes.

There is no field (name) data in the update debug message, so the issue might be related to something in the TracForm definition. Care to post your relevant wiki code?

Do you see 'form details' link in the context menu? If yes, what information can you derive from the form details view?

Your db backend is default SQLite, or anything else?

Do you have skills to query the db directly? I might need to know what's stored in relevant db tables forms, forms_fields and forms_history.

[tracformsTrachacks@…]

First, thank you for your quick reply

Did you try to get advise on the mailing list (th-users) first? That's preferred, since this is a development tracking system.

No, I did not knew, there was a mailing list, but I will cross-post this today, when I have some time left..

Care to post your relevant wiki code?

I used the standard sample in this case:

|| || '''Who''' || '''When''' || '''What''' ||
|| [tf:wash] || [tf.who:wash] || [tf.when:wash] || Wash Clothes ||
|| [tf:dry] || [tf.who:dry] || [tf.when:dry] || Dry Clothes ||
|| [tf:fold] || [tf.who:fold] || [tf.when:fold] || Fold Clothes ||

but I also wrote some forms myself already.

Do you see 'form details' link in the context menu? If yes, what information can you derive from the form details view?

Which context-menu do you mean exactly?

Your db backend is default SQLite, or anything else?

Thats what I forgot, its MySQL with MyISAM-backend :)

Do you have skills to query the db directly? I might need to know what's stored in relevant db tables forms, forms_fields and forms_history.

Here is a dump of the tables (only the content, the structure should be okay, I think):

INSERT INTO forms (id, realm, resource_id, subcontext, state, author, `time`, keep_history, track_fields) VALUES
(7, 'wiki', 'WikiStart', '', '{"dry":"on","fold":"on","wash":"on"}', 'j_heller', 1319023921, NULL, NULL);

INSERT INTO forms_fields (id, field, author, `time`) VALUES
(7, 'wash', 'j_heller', 1319023921),
(7, 'fold', 'j_heller', 1319023921),
(7, 'dry', 'j_heller', 1319023921);

forms_history is empty...

[Steffen Hoffmann]

Replying to tracformsTrachacks@mailfoo.doenerbier.de:

Care to post your relevant wiki code?

I used the standard sample in this case:

Ok, I see.

Which context-menu do you mean exactly?

After TracForms data has been saved for a given resource (ticket or wiki page), you'll see a link to form details in the context navigation, that is right below the Trac mainnav bar. Clicking there will take you to form details, and you'll notice that it's looking similar to change history for tickets, just on a separate page.

Your db backend is default SQLite, or anything else?

Thats what I forgot, its MySQL with MyISAM-backend :)

No own experience with that, but good to know anyway.

Do you have skills to query the db directly? I might need to know what's stored in relevant db tables forms, forms_fields and forms_history.

Here is a dump of the tables (only the content, the structure should be okay, I think): ![...] forms_history is empty...

This looks good. forms_history will only fill on second and later changes, if keep_history is set to 'yes' (defaults to 'no') - always with the old state from forms ('{"dry":"on","fold":"on","wash":"on"}' in this example). So let's concentrate on this situation: updating forms after first time.

Maybe, there's something special that is related to your backend. SQLite is certainly fine, but this is the most forgiving, if there are any bugs in the code. Will have a look, but may need more debug information.

[tracformsTrachacks@…]

Replying to hasienda:

After TracForms data has been saved for a given resource (ticket or wiki page), you'll see a link to form details in the context navigation, that is right below the Trac mainnav bar. Clicking there will take you to form details, and you'll notice that it's looking similar to change history for tickets, just on a separate page.

Okay, got it now. It only appears if you edit the wiki-Page, where the form is located.

After I reset the form, the database now looks like that:

INSERT INTO `forms` (`id`, `realm`, `resource_id`, `subcontext`, `state`, `author`, `time`, `keep_history`, `track_fields`) VALUES
(7, 'wiki', 'WikiStart', '', '{}', 'j_heller', 1319186304, NULL, NULL);

and forms_fields is now also empty, but I am still not able to change the form. However, if I delete the row from forms, I am in the beginning state and can check the form once again, so it has probably something to do with the UPDATE-Statement (unfortunatly I am not that py-expert, so I don't know how this is done here)

Maybe, there's something special that is related to your backend. SQLite is certainly fine, but this is the most forgiving, if there are any bugs in the code. Will have a look, but may need more debug information.

Okay, I am eager to help ;)

This is where my Trac-Installation is probably located (because I installed exactly this version as an egg):
/usr/local/lib/python2.6/dist-packages/Trac-0.12.2-py2.6.egg

Can I change files in this directory and directly see the changes in the software (after reloading apache because I use mod_python of course)?
Where is the code regarding the database located. Maybe you can point me out to some important lines, so I could do some testing myself...

[Steffen Hoffmann]

Replying to tracformsTrachacks@mailfoo.doenerbier.de:

Replying to hasienda:

After TracForms data has been saved for a given resource (ticket or wiki page), you'll see a link to form details ![...] that it's looking similar to change history for tickets, just on a separate page.

Okay, got it now. It only appears if you edit the wiki-Page, where the form is located.

Not right, should be always there, not only in editor mode (<wiki_page_name>?action=edit), but let's postpone this until the main issue is resolved.

After I reset the form, the database now looks like that:

Again looks correct.

and forms_fields is now also empty, but I am still not able to change the form. However, if I delete the row from forms, I am in the beginning state and can check the form once again, so it has probably something to do with the UPDATE-Statement (unfortunatly I am not that py-expert, so I don't know how this is done here)

I agree. Will have a look and translate as much for you as needed to understand.

This is where my Trac-Installation is probably located ![...] Can I change files in this directory and directly see the changes in the software (after reloading apache because I use mod_python of course)?
Where is the code regarding the database located. Maybe you can point me out to some important lines, so I could do some testing myself...

Don't touch anything in there. The plugin code is separate, and we certainly want to fix that, not Trac core functionality. Db actions for TracForms are concentrated in tracforms/formdb.py (hence it has it's name). All we may need is to test with modified plugin code. As I progress I may put out some patch file for debugging and/or testing preliminary changes.

[Steffen Hoffmann]

I'll give you some details about what's going on after you hit forms submit button:

POST request is captured and processed by class FormUpdater in api.py, see the IRequestHandler method process_request. BTW, the interface definition of IRequestHandler is imported from trac/web/api.py through `trac/web/init.py . If you're not so familiar with the overall concept have a look at ​T:wiki:TracDev/ComponentArchitecture first.

Now, in process_request spot the call to self.save_tracform. Before you look up and down a hundred times in FormUpdater to (not) find that module, note that this class inherits FormDBUser class, what bundles all classes implementing the IFormDBObserver interface. There you'll find the save_tracform method calling save_tracform method(s) of registered IFormDBObserver implementations. By default just FormDBComponent implements(IFormDBObserver), see tracforms/formdb.py as hinted above.

Down there in FormDBComponent.save_tracform() the process runs roughly like so:

• eval the form data, that shall be saved
  • check, if we have seen that form before or just write 1st time for this form, with help by self.get_tracform_meta method and other logic
  • check, if we're required to track changes per field (track_fields) and preserve field history (keep_history)
• if no form id has been found, do INSERT
• otherwise to UPDATE
• optionally INSERT previous field values into Trac db table forms_history
• optionally too
  • find updated fields
  • loop over the list of updated fields and check it's presence by COUNTing their presence in forms_fields (should normally be 0 or 1)
  • depending on that INSERT or UPDATE recorded field content

Hope this get's you started.

[Steffen Hoffmann]

The way to go now would be to add some more self.log.debug() lines and find, where execution breaks. Considering your descriptions this must be one of the last 3 main steps following the . We'll need to check arguments, because there is something missing there.

[logging]
log_file = trac.log
log_level = DEBUG
log_type = file

[trac]
debug_sql = false

or similar environment configuration in trac.ini will help to get most verbose logging output. Especially the debug_sql will show all arguments prepared for SQL statements too. What ever is going wrong, it should show up there.

[rumble]

Hi there,

sorry for late response. I took over the problem. I have changed trac.ini as you said, but I do not know what may be wrong.

My Form looks like:

{{ { #TracForm
#
# An example of a TracForm. The first lines can be commentary or #! commands.
#
#! track_fields

| | | | Who | | When | | What | |
| | [tf:wash] | | [tf.who:wash] | | [tf.when:wash] | | Wash Clothes | |
| | [tf:dry] | | [tf.who:dry] | | [tf.when:dry] | | Dry Clothes | |
| | [tf:fold] | | [tf.who:fold] | | [tf.when:fold] | | Fold Clothes | |

}}}

I may send you a greater extract of the log later on. Following massage appears for every argument:

2011-11-08 10:22:20,710 Trac[util] DEBUG: SQL: '\n SELECT author, time\n FROM forms_fields\n WHERE id=%s\n AND field=%s\n '
2011-11-08 10:22:20,710 Trac[util] DEBUG: args: (8L, u'wash')
2011-11-08 10:22:20,710 Trac[macros] DEBUG: TracForms value: unknown

[tracformsTrachacks@…]

I think the problem is rather here:

2011-11-18 11:09:56,390 Trac[api] DEBUG: UPDATE ARGS:{'__backpath__': u'/admintrac/wiki/Rechnerinstallation', '__FORM_TOKEN': u'8654fdcda60352c4cbd0ae2f', '__track_fields__': u'yes', '__basever__': u'1321350737', '__context__': u'["wiki","Rechnerinstallation",""]'}
2011-11-18 11:09:56,390 Trac[util] DEBUG: SQL: '\n            SELECT  id,\n                    realm,\n                    resource_id,\n                    subcontext,\n                    author,\n                    time,\n                    keep_history,\n                    track_fields\n            FROM    forms\n            \n                WHERE   realm=%s\n                    AND resource_id=%s\n                    AND subcontext=%s\n                '
2011-11-18 11:09:56,390 Trac[util] DEBUG: args: [u'wiki', u'Rechnerinstallation', u'']
2011-11-18 11:09:56,391 Trac[util] DEBUG: SQL: '\n            SELECT  state\n            FROM    forms\n            \n                WHERE   realm=%s\n                    AND resource_id=%s\n                    AND subcontext=%s\n                '
2011-11-18 11:09:56,391 Trac[util] DEBUG: args: 9L
2011-11-18 11:09:56,391 Trac[util] DEBUG: execute exception: TypeError('not enough arguments for format string',)

Replying to rumble:

Hi there,

sorry for late response. I took over the problem. I have changed trac.ini as you said, but I do not know what may be wrong.

My Form looks like:

{{ { #TracForm
#
# An example of a TracForm. The first lines can be commentary or #! commands.
#
#! track_fields

| | | | Who | | When | | What | |
| | [tf:wash] | | [tf.who:wash] | | [tf.when:wash] | | Wash Clothes | |
| | [tf:dry] | | [tf.who:dry] | | [tf.when:dry] | | Dry Clothes | |
| | [tf:fold] | | [tf.who:fold] | | [tf.when:fold] | | Fold Clothes | |

}}}

I may send you a greater extract of the log later on. Following massage appears for every argument:

2011-11-08 10:22:20,710 Trac[util] DEBUG: SQL: '\n SELECT author, time\n FROM forms_fields\n WHERE id=%s\n AND field=%s\n '
2011-11-08 10:22:20,710 Trac[util] DEBUG: args: (8L, u'wash')
2011-11-08 10:22:20,710 Trac[macros] DEBUG: TracForms value: unknown

[Steffen Hoffmann]

Replying to tracformsTrachacks@mailfoo.doenerbier.de:

I think the problem is rather here:
... execute exception: TypeError('not enough arguments for format string',)

That looks like something to take care for, indeed. Thanks for this log snippet.

[Steffen Hoffmann]

(In [10924]) TracFormsPlugin: Replace rather too narrow check for IntType, refs #9286.

Following up to complaint raised by users of db backends other than SQLite, notably MySQL, it seems unwise to any longer rely on form-IDs being int-only, seen i.e. LongType too. So let's go with a check for just numbers.

[Steffen Hoffmann]

With the latest log all facets of your observations could be explained.

The key was actually here:

2011-11-08 10:22:20,710 Trac[util] DEBUG: args: (8L, u'wash') 
                                                 ^^

hinting that your db backend returns type Long instead of expected Int for the form-ID. This is the primary access key to all but the initial date save. You see the pattern?

Of course I'm still eager to learn, if this fixes your problems. This would make another good reason to release a new version. And that would ultimately close this ticket then.

So report your findings here, please.

[Steffen Hoffmann]

Three months should have been plenty of time to test this.

Still no in-dependent test feedback? That's a bit disappointing to me.

[Steffen Hoffmann]

This issue seems resolved and will be closed by the time of next stable plugin release.

[djones@…]

Replying to hasienda:

This issue seems resolved and will be closed by the time of next stable plugin release.

Please hold this open for a little longer. I seem to be experiencing a similar problem. I will try to confirm this over the next few days. My setup:

Trac-0.12.4 CentOS 6 MySQL Apache (wsgi)

FWIW, I do not think the issue is with a Long vice an Int, as suggested in the post dated 11/18/11. My log data does not show the number with a trailing 'L'

[Steffen Hoffmann]

Not being able to save form data more than once would be enough to force more actions than what I've seen within last 14 months - no feedback to my attempted fix + explanation of the issue. A significant number if users here just take the software or fix and never return, if they're happy. Maintainers later have to make decisions on their own, and that's what I've been doing here. Thank you for stepping-up to provide more information. I'm looking forward to hearing from you.

Replying to hasienda:

Replying to tracformsTrachacks@mailfoo.doenerbier.de:

Replying to hasienda:

After TracForms data has been saved for a given resource (ticket or wiki page), you'll see a link to form details ![...] that it's looking similar to change history for tickets, just on a separate page.

Okay, got it now. It only appears if you edit the wiki-Page, where the form is located.

Not right, should be always there, not only in editor mode (<wiki_page_name>?action=edit), but let's postpone this until the main issue is resolved.

While at it, this might be yet another thing to care for when testing. I couldn't reproduce this as well, but I'll give it a try in one of my recently added PostgreSQL test environments.

PostgreSQL is great for tracking issues down, because its so strict about types and SQL syntax. When looking at SQLite at the very permissive side, from my point of view MySQL is in-between, and sometimes its just a bit wired.

[djones@…]

Had a chance to do some testing, and it appears that the problem is indeed with typing of data.

The setup that I have fails in formdb.py, in function get_tracform_state(), line 95,

"        if not isinstance(src, int):"

at this point, src = '3', so the expected value of isinstance(src, int) is True. However, it yields False. (!) Apparently MySQLdb is treating the result of the query as a string. As a result, the following code tries to return a query with three parameters, but src is only providing one.

88        def get_tracform_state(self, src, db=None):
89 	        db = self._get_db(db)
90 	        cursor = db.cursor()
91 	        sql = """
92 	            SELECT  state
93 	            FROM    forms
94 	            """
95 	        if not isinstance(src, int):
96 	            sql += """
97 	                WHERE   realm=%s
98 	                    AND resource_id=%s
99 	                    AND subcontext=%s
100 	                """
101 	        else:
102 	            sql += """
103 	                WHERE   id=%s
104 	                """
105 	            src = tuple([src],)
106 	        cursor.execute(sql, src)

This particular case could be fixed by checking for src being a list or tuple (must check both) rather than an integer. For instance, line 661 has

if isinstance(value, (list, tuple)):

I tried such a fix, only to discover it failed somewhere else.

I see that the technique of using

isinstance(src,int)

is used extensively in the module. I haven't analyzed the code logic to see whether all of those occurrences could be replaced with

isinstance(value, (list, tuple))

or not. As the author, you could probably make that call much more effectively. I think doing so would make it more resilient to changes in how various databases (and python db interface modules) handle data types.

I have a log file if you are interested. It is on a different system, so I would have to add it later.

[Steffen Hoffmann]

Replying to djones@mitre.org:

Had a chance to do some testing, and it appears that the problem is indeed with typing of data.

The setup that I have fails in formdb.py, in function get_tracform_state(), line 95,

...

I have a log file if you are interested. It is on a different system, so I would have to add it later.

I'd say YES under similar circumstances.

But reading your latest comment I realized, that we're looking at different code, and I'd rather like you to test current trunk code, before we go any further on this issue.

In development code you'll notice, that I've already dropped most of the isinstance tests in favor of an even more generic utility function is_number. Actually it's what [10924], dedicated to this ticket, is all about. This should cover the observed behavior as well, even if I feel, that it is a bit nasty to return string while all relevant db tables 'id' columns are defined with type int explicitly.

[djones@…]

Downloaded trunk (r11562). Initial testing indicates that this does indeed fix the problem.

Since some people (like me) prefer to download the version labeled as "stable", perhaps now would be a good time to link to a newer version (post-10924 anyway) as "stable" from the wiki page.

[Steffen Hoffmann]

Replying to djones@mitre.org:

Downloaded trunk (r11562). Initial testing indicates that this does indeed fix the problem.

Great.

Since some people (like me) prefer to download the version labeled as "stable", perhaps now would be a good time to link to a newer version (post-10924 anyway) as "stable" from the wiki page.

I'll consider this. Actually I've been thinking the same when reviewing commit history for answering your comments. I must have had some development objectives, that I don't remember exactly right now. At least some work related to read-only and conditionally locked fields was not finished. I'll sort this out. Please nudge me again, if you feel it takes too long. Thanks for taking care.

Btw, the next release cycle will include unit testing, that I adopted as mandatory requirement after doing most of recent development for this plugin. That should count much more than the stable release marker. If not just for using it in daily business on my own, I feel confident about the code due to the low issue frequency in recent history.

[Tiago Teresa Teodósio]

I confirm this issue in 'stable' release 0.4.1 using MySQL database. I also confirm this is fixed in 'trunk' version 0.5dev.