Never-Ending Header Update

[andz]

The first update of specific newsgroups seems to never end, because it resets to 0% every few hours.

During hours of upgrading the following messages occur every few minutes:

Code:

2009-01-02 08:47:29 NOTICE Skipping -2361815 articles while updating alt.binaries.erotica
2009-01-02 08:43:14 NOTICE Notice on line 469 in file /var/www/urd/functions/nntp.class.php: Undefined offset: 1 (8)

With debug on:

Code:

2009-01-02 11:41:40 DEBUG fn:do_diskfree() pid:11390 (5767168 5767168)
2009-01-02 11:41:40 DEBUG fn:do_diskfree() pid:11390 (5767168 5767168)
2009-01-02 11:41:40 DEBUG fn:check_schedule() pid:11390 (5767168 5767168)
2009-01-02 11:41:40 DEBUG fn:check_queue() pid:11390 (5767168 5767168)
2009-01-02 11:41:40 DEBUG read line: [DISKFREE b]
2009-01-02 11:41:40 DEBUG fn:read_sockets() pid:11390 (5767168 5767168)
2009-01-02 11:41:39 NOTICE Skipping -25828 articles while updating alt.binaries.erotica
2009-01-02 11:41:38 DEBUG fn:check_schedule() pid:11390 (5767168 5767168)
2009-01-02 11:41:38 DEBUG fn:check_queue() pid:11390 (5767168 5767168)
2009-01-02 11:41:36 DEBUG fn:check_schedule() pid:11390 (5767168 5767168)
2009-01-02 11:41:36 DEBUG read line: [USER andz]
2009-01-02 11:41:36 DEBUG fn:check_queue() pid:11390 (5767168 5767168)
2009-01-02 11:41:36 DEBUG fn:read_sockets() pid:11390 (5767168 5767168)
2009-01-02 11:41:36 DEBUG fn:check_schedule() pid:11390 (5767168 5767168)
2009-01-02 11:41:36 DEBUG read line: [PASS md5:f910522c2c221dd183099d785efb2d2b]

My provider is ngroups and this happens just with really big newsgroups (20M+). I noticed this problem in 0.5.5, but right now I'm using r403 and it's still there.

Is there an option to limit the first header update?

[spearhead]

Interesting... esp the negative number it is skipping.

I added a debug line. Could you update to r 404, restart urdd and see what the debug line right before "skipping ..." says. Should be of the form "from: XXX ; to: YYY ; art: ZZZ ; x: TTT"?

[andz]

Just did the update and the debug output is:

Code:

2009-01-02 14:05:46 DEBUG fn:add_parts() pid:25315 (6029312 6029312)
2009-01-02 14:05:45 DEBUG from: ; to: 189785605 ; art: 189747823 ; x: 189783606
2009-01-02 14:05:45 NOTICE Notice on line 546 in file /var/www/urd/functions/nntp.class.php: Undefined variable: msggrom (8)
2009-01-02 14:05:45 DEBUG fn:add_parts() pid:25315 (6029312 6029312)
2009-01-02 14:05:45 NOTICE Skipping -35783 articles while updating alt.binaries.erotica

I've been updating for about 24h on 5 groups and noticed that the mysql db is quite huge:

Code:

sudo du -sh /var/lib/mysql/urd/
29G     /var/lib/mysql/urd/

[Styck]

That is huge indeed.
For me:
5.1G    /var/lib/mysql/urd

For 7 (rather big but not huge like boneless/core) newsgroups, 5 day retention.

[andz]

Oh perhaps this size is normal then.

I got subscribed to these 3 which are worth to mention:
a.b.tv, a.b.erotica, a.b.hdtv.x264

But 150+ day retention...

Can I limit the first upgrade to just a few days?

[andz]

Now the update is finished:

Code:

2009-01-02 15:13:50 NOTICE Updating binary info for alt.binaries.erotica
2009-01-02 15:14:15 NOTICE Updating set info for alt.binaries.erotica

But no headers are available.

[spearhead]

Can I limit the first upgrade to just a few days?

Yes in newsgroups tab you can set the "expire" field in nr of days.

[spearhead]

Now the update is finished:

Code:

2009-01-02 15:13:50 NOTICE Updating binary info for alt.binaries.erotica
2009-01-02 15:14:15 NOTICE Updating set info for alt.binaries.erotica

But no headers are available.

Does it work with smaller groups, eg a.b.multimedia.scifi-and-fantasy or a.b.sounds.mp3.heavy-metal

[andz]

I tried to limit a.b.erotica to 3 days, but that doesn't seem to work the problem reoccurs.
(Previously I purged and unsubscribed from all newsgroups and my db shrank to 4mb. From the description of Expire I thought that articles are kept in my db for n days...)

Code:

2009-01-02 19:02:50 DEBUG fn:add_parts() pid:31431 (6029312 6291456)
2009-01-02 19:02:50 NOTICE Notice on line 546 in file /var/www/urd/functions/nntp.class.php: Undefined variable: msggrom (8)
2009-01-02 19:02:50 DEBUG fn:check_schedule() pid:31356 (5767168 5767168)
2009-01-02 19:02:50 DEBUG from: ; to: 189785795 ; art: 189749903 ; x: 189783796
2009-01-02 19:02:50 NOTICE Skipping -33893 articles while updating alt.binaries.erotica

I don't have any problems with smaller newsgroups like alt.sounds.lossless.rock

Shall I give r406 a try?

[spearhead]

Please do I have a little hunch at what may be wrong so I added another debug msg and fixed the previous one...

[andz]

Ok, same problem, but output is now like this:

Code:

2009-01-02 22:50:25 DEBUG fn:add_parts() pid:7503 (6029312 6029312)
2009-01-02 22:50:24 NOTICE Select failed 189782787: No such article found (No Such Article)
2009-01-02 22:50:24 NOTICE Skipping -33984 articles while updating alt.binaries.erotica
2009-01-02 22:50:24 DEBUG from: 189780788 ; to: 189782787 ; art: 189746804 ; x: 189780788
2009-01-02 22:50:24 DEBUG fn:add_parts() pid:7503 (6029312 6029312)
2009-01-02 22:50:24 DEBUG fn:add_parts() pid:7503 (6029312 6029312)

looking at how there are negative values in the log-output, it makes me wonder if the possible cause might be an integer overflow?

[spearhead]

Looking at the numbers I don't think it is an int overflow.

Can you try to telnet or (netcat) to your news server?

like:

Code:

telnet newsserver 119

in case you need a username and password type (fill in username and password) otherwise you can skip these:

Code:

authinfo user username
authinfo pass password

then type

Code:

group alt.binaries.erotica
next

And post the line you get in return from the next... should look like

Code:

223 49067 <TvudnW3RjNPH6o3UnZ2dnUVZ8uidnZ2d@giganews.com> Article retrieved; request text separately.

[Styck]

What seems to happen is this:

1) URDD estimates that it should download all the articles from messageID 189780788 to messageID 189782787

2) URDD tries to download these messages, but the first batch of messages (should be 2000 of em IIRC) is empty because the downloads failed.

3) URDD figures 'ok, this can happen' and asks the news server for the 'next' messageID, this should be the first valid article number.

4) The news server comes up with 189746804. URDD then uses this as the new starting point.

5) What could happen (assumption here) is that URDD goes on as usual, and ultimately comes back to the 189780788 to 189782787 range, where it jumps back again to 189746804 and comes into an infinite loop.

Solution: Prevent jumping back. But why does this happen? Preventing negative skipping could cause faulty updates and missing articles. Maybe it's best if we look into that first...

(The above post might shed some light in this case)

[andz]

np

Code:

andz@andz:/var/www/urd$ telnet  news.us.ngroups.net 119
Trying 69.16.185.250...
Connected to newsfarm.iad.highwinds-media.com.
Escape character is '^]'.
200 (newsfe02.iad Welcome) (newsfe02.iad) (Tornado v1.2.3.534.1)
authinfo user ************
381 More Authentication Required
authinfo pass ************
281 Welcome @Space UseNET - http://WWWSpace.NET/usenet
group alt.binaries.erotica
211 89061477 189745358 278806834 alt.binaries.erotica
next
223 189745395 <48483058$0$4693$6f24588e@up.download2day.nl>

[andz]

I tried r407 right now and the output looks like this:

Code:

2009-01-03 14:00:38 NOTICE Select failed 189785277: No such article found (No Such Article)
2009-01-03 14:00:38 NOTICE Skipping -15660 articles while updating alt.binaries.erotica
2009-01-03 14:00:38 DEBUG from: 189783278 ; to: 189785277 ; art: 189767618 ; x: 189783278
2009-01-03 14:00:38 DEBUG fn:add_parts() pid:14446 (6029312 6029312)
2009-01-03 14:00:37 DEBUG fn:check_queue() pid:14442 (5767168 5767168)

Is it a problem that articles are expiring really fast in that huge ng?

[andz]

and another log, using r408.

Code:

2009-01-03 15:52:44 NOTICE Incoherent article number received: 190164493
2009-01-03 15:52:44 NOTICE Select failed 192677394: No such article found (No Such Article)
2009-01-03 15:52:44 NOTICE Skipping -2508902 articles while updating alt.binaries.erotica
2009-01-03 15:52:43 NOTICE Skipping -2517780 articles while updating alt.binaries.erotica
2009-01-03 15:52:43 DEBUG from: 192669395 ; to: 192671394 ; art: 190151615 ; x: 192669395
2009-01-03 15:52:43 NOTICE Select failed 192671394: No such article found (No Such Article)
2009-01-03 15:52:43 NOTICE Select failed 192673394: No such article found (No Such Article)
2009-01-03 15:52:43 NOTICE Incoherent article number received: 190151615
2009-01-03 15:52:43 NOTICE Incoherent article number received: 190152749
2009-01-03 15:52:43 NOTICE Skipping -2518646 articles while updating alt.binaries.erotica
2009-01-03 15:52:43 DEBUG from: 192671395 ; to: 192673394 ; art: 190152749 ; x: 192671395
2009-01-03 15:52:42 DEBUG fn:check_schedule() pid:16656 (5767168 5767168)
2009-01-03 15:52:42 DEBUG fn:check_queue() pid:16656 (5767168 5767168)
2009-01-03 15:52:42 DEBUG fn:do_diskfree() pid:16656 (5767168 5767168)
2009-01-03 15:52:42 DEBUG fn:read_sockets() pid:16656 (5767168 5767168)
2009-01-03 15:52:42 DEBUG fn:read_sockets() pid:16656 (5767168 5767168)
2009-01-03 15:52:42 DEBUG read line: [DISKFREE b]
2009-01-03 15:52:42 NOTICE Incoherent article number received: 190151070
2009-01-03 15:52:42 NOTICE Skipping -2516325 articles while updating alt.binaries.erotica
2009-01-03 15:52:42 DEBUG fn:check_queue() pid:16656 (5767168 5767168)
2009-01-03 15:52:42 DEBUG from: 192667395 ; to: 192669394 ; art: 190151070 ; x: 192667395
2009-01-03 15:52:42 NOTICE Select failed 192669394: No such article found (No Such Article)
2009-01-03 15:52:42 DEBUG fn:check_queue() pid:16656 (5767168 5767168)
2009-01-03 15:52:42 DEBUG fn:check_schedule() pid:16656 (5767168 5767168)

[spearhead]

5) What could happen (assumption here) is that URDD goes on as usual, and ultimately comes back to the 189780788 to 189782787 range, where it jumps back again to 189746804 and comes into an infinite loop.

What actually happens is that a STAT nnn is run on the server / group (where nnn is the last msg we tried to get) and then a NEXT. Both manipulate the internal server pointers (STAT sets in, NEXT advances it). If the STAT fails however, the pointer is not set and NEXT returns the next valid article after the pointer, which is earlier.

[andz]

latest log from r409...

Code:

2009-01-03 16:54:00 NOTICE Incoherent article number received: 189760747
2009-01-03 16:54:00 NOTICE Skipping -1460209 articles while updating alt.binaries.erotica
2009-01-03 16:54:00 DEBUG from: 191220956 ; to: 191222955 ; art: 189760747 ; x: 191220956
2009-01-03 16:54:00 NOTICE Select failed 191222955: No such article found (No Such Article)
2009-01-03 16:54:00 NOTICE Select failed 191224955: No such article found (No Such Article)
2009-01-03 16:54:00 DEBUG from: 191222956 ; to: 191224955 ; art: 189760755 ; x: 191222956
2009-01-03 16:54:00 NOTICE Incoherent article number received: 189760755
2009-01-03 16:54:00 NOTICE Skipping -1462201 articles while updating alt.binaries.erotica
2009-01-03 16:53:59 DEBUG fn:add_parts() pid:17866 (6029312 6029312)
2009-01-03 16:53:59 DEBUG fn:add_parts() pid:17866 (6029312 6029312)
2009-01-03 16:53:59 DEBUG fn:check_schedule() pid:17865 (5767168 5767168)
2009-01-03 16:53:59 DEBUG fn:add_parts() pid:17866 (6029312 6029312)
2009-01-03 16:53:59 DEBUG fn:check_queue() pid:17865 (5767168 5767168)
2009-01-03 16:53:59 DEBUG fn:add_parts() pid:17866 (6029312 6029312)
2009-01-03 16:53:58 NOTICE Select failed 191212955: No such article found (No Such Article)
2009-01-03 16:53:58 DEBUG from: 191210956 ; to: 191212955 ; art: 189760730 ; x: 191210956
2009-01-03 16:53:58 DEBUG fn:add_parts() pid:17866 (6029312 6029312)
2009-01-03 16:53:58 NOTICE Incoherent article number received: 189760730
2009-01-03 16:53:58 NOTICE Skipping -1450226 articles while updating alt.binaries.erotica

[spearhead]

I fixed a number of smaller and rarer bugs.... see if it helps

[andz]

r410 started without minus skipping:

Code:

2009-01-03 23:52:35 DEBUG Guessed pointer: 278802363 (between 189745395 and 279224278)
2009-01-03 23:52:35 NOTICE Getting headers 189745395 to 279224278
2009-01-03 23:52:35 DEBUG fn:guess_first_article() pid:24968 (5767168 5767168)
2009-01-03 23:52:35 DEBUG fn:get_headers() pid:24968 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:restore_old_queue() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:server() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:queue_update() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG pushing on the queue
2009-01-03 23:52:34 NOTICE Restored 'UPDATE 1082'
2009-01-03 23:52:34 DEBUG pushing on the queue 185
2009-01-03 23:52:34 DEBUG fn:__destruct() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:set_handlers() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:disconnect() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:reload_scheduled_jobs() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:__destruct() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:disconnect() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:disconnect() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:__destruct() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:listen_socket() pid:24967 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:connect_nntp() pid:24968 (5767168 5767168)
2009-01-03 23:52:34 DEBUG fn:update_newsgroup() pid:24968 (5767168 5767168)
2009-01-03 23:52:34 INFO Connecting to NNTP server: news.us.Ngroups.NET
2009-01-03 23:52:34 NOTICE Determining first articles number for alt.binaries.erotica

But had a disconnect later and it started over:

Code:

2009-01-04 02:09:37 ERROR Cannot connect to server: news.us.Ngroups.NET
2009-01-04 02:09:37 WARNING Warning on line 154 in file /var/www/urd/functions/libs/socket.php: fsockopen(): unable to connect to tcp://news.us.Ngroups.NET:119 (Connection timed out) (2)
2009-01-04 02:09:37 DEBUG fn:__destruct() pid:26746 (5767168 5767168)
2009-01-04 02:09:37 DEBUG fn:disconnect() pid:26746 (5767168 5767168)
2009-01-04 02:09:37 DEBUG fn:kill_handler() pid:26746 (5767168 5767168)
2009-01-04 02:09:37 INFO sighandler (signal: 0) called as child
2009-01-04 02:09:34 DEBUG read line: [PASS md5:f910522c2c221dd183099d785efb2d2b]
2009-01-04 02:09:34 DEBUG read line: [USER andz]
2009-01-04 02:09:34 DEBUG Incoming connection from host localhost:54883
2009-01-04 02:09:34 DEBUG read line: [DISKFREE h]
2009-01-04 02:09:34 DEBUG fn:do_diskfree() pid:24967 (5767168 5767168)
2009-01-04 02:09:34 DEBUG read line: [DISKFREE b]
2009-01-04 02:09:34 DEBUG fn:do_diskfree() pid:24967 (5767168 5767168)
2009-01-04 02:09:30 DEBUG read line: [USER andz]
2009-01-04 02:09:30 DEBUG Incoming connection from host localhost:54882
2009-01-04 02:09:30 DEBUG read line: [PASS md5:f910522c2c221dd183099d785efb2d2b]
2009-01-04 02:09:30 DEBUG read line: [DISKFREE h]
2009-01-04 02:09:30 DEBUG fn:do_diskfree() pid:24967 (5767168 5767168)
2009-01-04 02:09:30 DEBUG read line: [DISKFREE b]
2009-01-04 02:09:30 DEBUG fn:do_diskfree() pid:24967 (5767168 5767168)
2009-01-04 02:09:26 DEBUG read line: [PASS md5:f910522c2c221dd183099d785efb2d2b]
2009-01-04 02:09:26 DEBUG Incoming connection from host localhost:54881
2009-01-04 02:09:26 DEBUG read line: [DISKFREE h]
2009-01-04 02:09:26 DEBUG read line: [USER andz]
2009-01-04 02:09:26 DEBUG fn:do_diskfree() pid:24967 (5767168 5767168)
2009-01-04 02:09:26 DEBUG fn:do_diskfree() pid:24967 (5767168 5767168)
2009-01-04 02:09:26 DEBUG read line: [DISKFREE b]
2009-01-04 02:09:22 DEBUG #9 {main}
2009-01-04 02:09:22 DEBUG #8 /var/www/urd/urdd/urdd.php(605): server(Array, Object(DatabaseConnection), Object(server_data))
2009-01-04 02:09:22 DEBUG fn:__destruct() pid:24968 (10223616 10485760)
2009-01-04 02:09:22 DEBUG #7 /var/www/urd/urdd/urdd.php(372): check_queue(Object(DatabaseConnection), Object(conn_list), Object(server_data))
2009-01-04 02:09:22 INFO sighandler (signal: 0) called as child
2009-01-04 02:09:22 DEBUG #6 /var/www/urd/urdd/urdd.php(246): handle_queue_item(Object(DatabaseConnection), Object(server_data), Object(action))
2009-01-04 02:09:22 DEBUG Child exited (rc: 10)
2009-01-04 02:09:22 DEBUG fn:kill_handler() pid:24968 (10223616 10485760)
2009-01-04 02:09:22 DEBUG fn:disconnect() pid:24968 (10223616 10485760)
2009-01-04 02:09:22 DEBUG #1 /var/www/urd/functions/libs/nntp_client.php(709): Base_NNTP_Client->cmdFastXOver('211041709-21104...')
2009-01-04 02:09:22 DEBUG #0 /var/www/urd/functions/libs/base_nntp_client.php(1197): Base_NNTP_Client->_handleUnexpectedResponse(0)
2009-01-04 02:09:22 ERROR Error while updating alt.binaries.erotica: Unexpected response: []
2009-01-04 02:09:22 ERROR Unexpected response: [] (0)
2009-01-04 02:09:22 DEBUG NNTP Connect error received
2009-01-04 02:09:22 DEBUG #2 /var/www/urd/functions/nntp.class.php(524): NNTP_Client->get_fast_overview(211041709, 211043708)
2009-01-04 02:09:22 DEBUG #4 /var/www/urd/urdd/do_functions.php(257): URD_NNTP->update_newsgroup(Array, Object(action))
2009-01-04 02:09:22 WARNING Cannot get messages:
2009-01-04 02:09:22 DEBUG #3 /var/www/urd/functions/nntp.class.php(345): URD_NNTP->get_headers(Array, '189745395', '279224278', Object(action))
2009-01-04 02:09:22 DEBUG #5 /var/www/urd/urdd/urdd.php(108): do_update(Object(action), Object(DatabaseConnection))

And now the update seems to be stalled:

Code:

2009-01-04 14:21:38 DEBUG Incoming connection from host localhost:42290
2009-01-04 14:21:38 DEBUG read line: [DISKFREE b]
2009-01-04 14:21:38 WARNING Cannot get messages:
2009-01-04 14:21:38 ERROR Unexpected response: [] (0)
2009-01-04 14:21:38 DEBUG fn:do_diskfree() pid:24967 (5767168 5767168)
2009-01-04 14:21:38 DEBUG fn:disconnect() pid:27062 (10223616 10747904)

But the Thread is still running:

Code:

Updating alt.binaries.erotica 88% Running 259m 16s 2009-01-03 23:52:34 14:21:38 745 articles/s - total 89525017 articles

Average speed is quite low and around 2000 articles/s

[spearhead]

Is it also still running in admin/control? (should be under threads)

[andz]

yeah, looks like:

Code:

#1. id:1 pid:27062 u:andz s:13 cmd:UPDATE 1082 active qt:57835.4560831 st:48899.630698

[spearhead]

did that thread actually ever finish?

[andz]

No it started over again and I upgraded to r414, but update was still very slow.
I'm trying r417, right now and it's really fast.
 

[andz]

r417 was really fast, but now again seems to run endlessly and very slow. I think this problem starts with an offset error:

Code:

2009-01-05 09:44:07 NOTICE Notice on line 469 in file /var/www/urd/functions/nntp.class.php: Undefined offset: 1 (8)
2009-01-05 09:14:07 NOTICE Notice on line 469 in file /var/www/urd/functions/nntp.class.php: Undefined offset: 1 (8)
2009-01-05 08:14:01 NOTICE Notice on line 469 in file /var/www/urd/functions/nntp.class.php: Undefined offset: 1 (8)
2009-01-05 07:13:56 NOTICE Notice on line 469 in file /var/www/urd/functions/nntp.class.php: Undefined offset: 1 (8)
2009-01-05 06:13:44 NOTICE Notice on line 469 in file /var/www/urd/functions/nntp.class.php: Undefined offset: 1 (8)
2009-01-05 05:43:50 NOTICE Notice on line 469 in file /var/www/urd/functions/nntp.class.php: Undefined offset: 1 (8)
2009-01-05 03:28:33 NOTICE Select failed 200711708: No such article found (No Such Article)
2009-01-05 03:28:31 NOTICE Select failed 200697708: No such article found (No Such Article)
2009-01-05 03:22:43 NOTICE Select failed 198827708: No such article found (No Such Article)
2009-01-05 03:06:49 NOTICE Select failed 193533708: No such article found (No Such Article)
2009-01-05 03:06:49 NOTICE Select failed 193535708: No such article found (No Such Article)