IOError: failed to write data

[Ryan J Ollos]

The following is found in the logs after the upgrade to 1.0.1. I'm not yet sure if it belongs to a plugin, or belongs to Trac.

2013-06-06 09:47:16,847 Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/main.py", line 497, in _dispatch_request
    dispatcher.dispatch(req)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/main.py", line 234, in dispatch
    req.send(output, content_type or 'text/html')
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/api.py", line 498, in send
    self.write(content)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/api.py", line 620, in write
    self._write(data)
IOError: failed to write data

[Ryan J Ollos]

This is probably a separate issue, but it occurs just prior in the log. Needs more investigation.

2013-06-06 09:45:38,814 Trac[main] WARNING: [218.6.15.69] HTTPInternalError: 500 Trac Error (<div class="message">Submission rejected as potential spam <ul><li>IP 218.6.15.69 blacklisted by list.blogspambl.com [2]</li></ul></div>)
2013-06-06 09:47:05,105 Trac[main] WARNING: [173.44.37.226] HTTPInternalError: 500 Trac Error (<div class="message">Submission rejected as potential spam <ul><li>Content contained these blacklisted patterns: '(?i)(?:diet|penis)[\W_]*(?:pills|enlargement)', '(?i)(?:[ck]asino|gambl(?:e|ing)|poker|(?:texas)?-?hold-?em|black-?jack|baccarr?at?|roulette|lott(?:o|ery)|jackpot|millionaires?|backgammon)', '(?i)&lt;a href=', '(?i)casino', '(?i)\[(?:url|link)=http://'</li><li>Maximum number of external links per post exceeded</li><li>SpamBayes determined spam probability of 88.56%</li></ul></div>)

[Jun Omae]

Replying to rjollos:

...
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/api.py", line 620, in write
    self._write(data)
IOError: failed to write data

We can ignore the exception.

The exception is raised from mod_wsgi when the client closed the connection. An IOError normally has a pair of errno and a message of the error. However, mod_wsgi raises an IOError with only the message.

​https://code.google.com/p/modwsgi/source/browse/mod_wsgi.c?name=mod_wsgi-3.3#3313

[Ryan J Ollos]

Thanks Jun. I guess we can close this then, after determining whether comment:1 is a problem.

[Ryan J Ollos]

Here's another I'm unsure of:

2013-06-06 09:37:52,912 Trac[main] ERROR: Internal Server Error:
Traceback (most recent call last):
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/main.py", line 497, in _dispatch_request
    dispatcher.dispatch(req)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/web/main.py", line 214, in dispatch
    resp = chosen_handler.process_request(req)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/search/web_ui.py", line 106, in process_request
    results = self._do_search(req, terms, filters)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/search/web_ui.py", line 214, in _do_search
    or [])
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/wiki/web_ui.py", line 774, in get_search_results
    shorten_result(text, terms))
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/db/api.py", line 182, in __exit__
    self.db.close()
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/db/pool.py", line 50, in close
    self._pool._return_cnx(cnx, self._key, self._tid)
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/db/pool.py", line 163, in _return_cnx
    assert (tid, key) in self._active
AssertionError:

[Jun Omae]

Replying to rjollos:

...
  File "/srv/trac-hacks.org/pve/lib/python2.6/site-packages/Trac-1.0.1-py2.6.egg/trac/db/pool.py", line 163, in _return_cnx
    assert (tid, key) in self._active
AssertionError:

I suppose that _fetch_tkt_tags() in tagsplugin leads the assertions when raising an IntegrityError. In this case, db.rollback() doesn't have been called.

tractags/ticket.py

@@ -49 +49 @@
     use_cache = False
 
     def __init__(self):
-        self._fetch_tkt_tags()
+        db = self.env.get_db_cnx()
+        try:
+            self._fetch_tkt_tags(db)
+            db.commit()
+        except:
+            db.rollback()
+            raise
         cfg = self.config
         cfg_key = 'permission_policies'
         default_policies = cfg.defaults().get('trac', {}).get(cfg_key)
@@ -188 +194 @@
 
     # Private methods
 
-    def _fetch_tkt_tags(self):
+    def _fetch_tkt_tags(self, db):
         """Transfer all relevant ticket attributes to tags db table."""
         # Initial sync is done by forced, stupid one-way mirroring.
         # Data aquisition for this utilizes the known ticket tags query.
-        db = self.env.get_db_cnx()
         fields = ["COALESCE(%s, '')" % f for f in self.fields]
         ignore = ''
         if self.ignore_closed_tickets:
@@ -225 +230 @@
                        (tagspace, name, tag)
                 VALUES (%s, %s, %s)
                 """, [(self.realm, str(tkt_id), tag) for tag in ticket_tags])
-        db.commit()
         self.log.debug('EXIT_TAG_SYNC')
 
     try:

[Steffen Hoffmann]

Replying to jun66j5:

I suppose that _fetch_tkt_tags() in tagsplugin leads the assertions when raising an IntegrityError. In this case, db.rollback() doesn't have been called.

I see, a good idea. I'll do that change shortly.

[Ryan J Ollos]

Replying to jun66j5:

We can ignore the exception.

The exception is raised from mod_wsgi when the client closed the connection. An IOError normally has a pair of errno and a message of the error. However, mod_wsgi raises an IOError with only the message.

Is there any way you know of that we could suppress the errors in the logs? The messages tend to appear many times per hour, and fill the logs quite a bit.

Another one that I see many times per hour is:

2013-08-15 23:06:43,923 Trac[patch] WARNING: Invalid unified diff content

[Ryan J Ollos]

Replying to hasienda:

Replying to jun66j5:

I suppose that _fetch_tkt_tags() in tagsplugin leads the assertions when raising an IntegrityError. In this case, db.rollback() doesn't have been called.

I see, a good idea. I'll do that change shortly.

Any chance to push this change soon in case it might help with #11147?

[Jun Omae]

Replying to rjollos:

Is there any way you know of that we could suppress the errors in the logs? The messages tend to appear many times per hour, and fill the logs quite a bit.

No way. Trac 1.0.2dev suppresses the noisy logs, see ​trac:r11842.

Another one that I see many times per hour is:

2013-08-15 23:06:43,923 Trac[patch] WARNING: Invalid unified diff content

Hmm, I don't know why.... It is related to ​trac:ticket:10840#comment:8?

[Ryan J Ollos]

Replying to jun66j5:

Replying to rjollos:

Is there any way you know of that we could suppress the errors in the logs? The messages tend to appear many times per hour, and fill the logs quite a bit.

No way. Trac 1.0.2dev suppresses the noisy logs, see ​trac:r11842.

Thanks! Good to know that a fix is on the way.

Another one that I see many times per hour is:

2013-08-15 23:06:43,923 Trac[patch] WARNING: Invalid unified diff content

Hmm, I don't know why.... It is related to ​trac:ticket:10840#comment:8?

It appears that should have been fixed in ​[t 11319], however it is a good clue. I haven't seen a visible problem on the Trac site with diff file rendering, so I'm thinking the warnings are harmless. I only mentioned because there are so many of them in the logs. I'll send you the most recent log file by email in case you have a chance to take a look.

[Jun Omae]

Replying to rjollos:

Another one that I see many times per hour is:

2013-08-15 23:06:43,923 Trac[patch] WARNING: Invalid unified diff content

Hmm, I don't know why.... It is related to ​trac:ticket:10840#comment:8?

It appears that should have been fixed in ​[t 11319], however it is a good clue. I haven't seen a visible problem on the Trac site with diff file rendering, so I'm thinking the warnings are harmless. I only mentioned because there are so many of them in the logs. I'll send you the most recent log file by email in case you have a chance to take a look.

Thanks for trac.log! Sorry, my late reply.

I investigated the warnings in trac.log. Probably, we can ignore them. For instance, the following text, a pair of {{{#diff and }}} and a blank line lead the same warning in auto-preview.

{{{#!diff

}}}

Otherwise, incomplete diff text might exist in somewhere, e.g. wiki, ticket comment, etc...

[Ryan J Ollos]

Replying to jun66j5:

I investigated the warnings in trac.log. Probably, we can ignore them. For instance, the following text, a pair of {{{#diff and }}} and a blank line lead the same warning in auto-preview.

Thanks. I see that was added in ​[trac 9711]. What do you think about changing the log level to info? To me, a warning is something that the administrator should take notice of, however invalid content in a page or attachment is not really anything that the administrator needs to care about.

[Jun Omae]

Agreed. However, I think the log level should be debug and log content variable. I don't think current message Invalid unified diff content is useful.

-            self.log.warning('Invalid unified diff content')
+            self.log.debug("Invalid unified diff content: %.40r... (%d "
+                           "characters)", content, len(content))

2015-03-28 05:58:35,257 Trac[patch] DEBUG: Invalid unified diff content: u'asdaddfdfsdf\ndfffffffffffffffsdff\nsd... (67 characters)

[Ryan J Ollos]

Thanks, Jun. I created ​trac:#12005.

[Ryan J Ollos]

Replying to hasienda:

Replying to jun66j5:

I suppose that _fetch_tkt_tags() in tagsplugin leads the assertions when raising an IntegrityError. In this case, db.rollback() doesn't have been called.

I see, a good idea. I'll do that change shortly.

JFTR, this was fixed in [13419] / #11147.

[Ryan J Ollos]

Replying to rjollos:

This is probably a separate issue, but it occurs just prior in the log. Needs more investigation.

2013-06-06 09:45:38,814 Trac[main] WARNING: [218.6.15.69] HTTPInternalError: 500 Trac Error (<div class="message">Submission rejected as potential spam <ul><li>IP 218.6.15.69 blacklisted by list.blogspambl.com [2]</li></ul></div>)
2013-06-06 09:47:05,105 Trac[main] WARNING: [173.44.37.226] HTTPInternalError: 500 Trac Error (<div class="message">Submission rejected as potential spam <ul><li>Content contained these blacklisted patterns: '(?i)(?:diet|penis)[\W_]*(?:pills|enlargement)', '(?i)(?:[ck]asino|gambl(?:e|ing)|poker|(?:texas)?-?hold-?em|black-?jack|baccarr?at?|roulette|lott(?:o|ery)|jackpot|millionaires?|backgammon)', '(?i)&lt;a href=', '(?i)casino', '(?i)\[(?:url|link)=http://'</li><li>Maximum number of external links per post exceeded</li><li>SpamBayes determined spam probability of 88.56%</li></ul></div>)

Opened ​trac:#12006 for this issue.

Everything noted in this ticket has now been addressed in separate tickets.