Opened 4 years ago

Closed 2 years ago

# IOError: failed to write data

Reported by: Owned by: Ryan J Ollos Ryan J Ollos normal TracHacks normal Steffen Hoffmann 1.0

### Description

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


### comment:1 follow-up:  17 Changed 4 years ago by 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>)


### comment:2 in reply to:  description ; follow-up:  7 Changed 4 years ago by Jun Omae

...
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.

### comment:3 Changed 4 years ago by Ryan J Ollos

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

### comment:4 follow-up:  5 Changed 4 years ago by 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:


### comment:5 in reply to:  4 ; follow-up:  6 Changed 4 years ago by Jun Omae

...
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

 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) # 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: (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:

### comment:6 in reply to:  5 ; follow-ups:  8  16 Changed 4 years ago by Steffen Hoffmann

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.

### comment:7 in reply to:  2 ; follow-up:  9 Changed 4 years ago by Ryan J Ollos

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


### comment:8 in reply to:  6 Changed 4 years ago by Ryan J Ollos

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?

### comment:9 in reply to:  7 ; follow-up:  10 Changed 4 years ago by Jun Omae

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?

### comment:10 in reply to:  9 ; follow-up:  11 Changed 4 years ago by Ryan J Ollos

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.

### comment:11 in reply to:  10 ; follow-up:  13 Changed 4 years ago by Jun Omae

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...

### comment:12 Changed 2 years ago by Ryan J Ollos

Status: new → accepted

### comment:13 in reply to:  11 Changed 2 years ago by Ryan J Ollos

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.

### comment:14 Changed 2 years ago by 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)


### comment:15 Changed 2 years ago by Ryan J Ollos

Thanks, Jun. I created trac:#12005.

### comment:16 in reply to:  6 Changed 2 years ago by Ryan J Ollos

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.

### comment:17 in reply to:  1 Changed 2 years ago by Ryan J Ollos

Resolution: → cantfix accepted → closed

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.

### Modify Ticket

Action
as closed The owner will remain Ryan J Ollos.
The resolution will be deleted. Next status will be 'reopened'.