Bugs and quirks in 1.0.5 (svn)

[thorwak]

Starting a new thread since we have a new version now, I hope that makes sense? It doesn't mean that the problems described are new to 1.0.5, just that they are tested in latest SVN rather than 1.0.4 stable.

Ontopic:
Maximum number of threads, NNTP connections etc doesn't seem to be applied "on the fly". Maybe it's not supposed to, but then it should say something like "You need to restart urdd for changes to take effect". It's hard to say if what I'm describing applies to all "number of threads/connections" settings or just some, but here is a solid example:

I had max nr of NNTP connections set to 5 in my usenet server settings. I also had max nr NNTP connection set to 5 in urdd settings ("configuration"). Total number of threads was set to 7. I had one group update going, and started a download, which meant this DL used 4 NNTP-connections. I then chose to do a "preview" from a set. Surprisingly, but quite cool, the group update was put on pause (or maybe on queue) and the preview file downloaded. Then, the free NNTP-connection was stolen by the DL, not quite as cool

I have seen unlogical behaviour concerning threads/connections happen before so I decided to investigate a bit more this time.. I tried just resuming the group update (header download) but nothing happens (no msg neither). I figure it's because all allowed NNTP connections are busy. I raise it to 10 in both usenet server config and urdd config, also increase number of threads. I still can't restart/resume the group update from the task list. I pause one of the downloaders - then the group update grabs a connections an continues, but the DL now uses only 4 NNTP connections even though there are 5 more now configured (and yes, my usenet server allows up to 50 connections). Starting another DL after the first one, without restarting urdd, still makes it use only 4 NNTP-connections (since the group update is still running)

This leads me to believe urdd does never re-read it's config unless restarted. Like said above, either user should be informed when changing urdd settings, but better if urdd re-reads it's settings. Either by polling every now and then, when starting a new task or by some interval, or if they can be "pushed" to the daemon somehow (signalling SIGHUP is sometimes used for this kinda thing)

Also, the behavior where preview "borrows" an NNTP-connection from another task is excellent - but it should always be returned to the previous owner (group update in this case). Also, I would feel safer if connections were borrowed from a file DL rather than a header download, but maybe I'm just being paranoid about this (it feels like it could more easily lead to things getting FUBAR)


(Sorry for the long text; I find it difficult to describe these things in shorter terms without resorting to statements like "urdd doesn't work properly sometimes" )

[spearhead]

You are basically correct. Some settings are updated on the fly (en/disable a server, posting, loglevel) but the connection count isn't. Basically as I would have to retrofit that into any of the existing connection counters (and there are 3 or 4 or so).

Also when an error occurs urd will temporarily reduce the number of reconnections in order to not spam the server too much. This should be automatically restored.

Preempted connections should get the highest priority in the queue after previews. Sometimes I notice that connection are run in unexplainable orders.... but I haven't really investigated this.

[thorwak]

I dunno - maybe one could just document in the help popups that a restart of urdd is needed for change of number connections and threads to take effect. It's not like one change these every 5 minutes, the important thing is things in general work as expected

[spearhead]

I 'll look into it... and see if I can do sth about that

[thorwak]

- Admin's email-address is still not saved from the installation script when doing a fresh install. Download path saving works now however.


- If one has an installation without any active usenet server (typical scenario after a fresh installation) and tries to start urdd, nothing (seems to) happen. In the logs, one can see that it tried to start up, and that one should activate at least one usenet server. urdd is shown as stopped. However, the process is still there (doesn't terminate itself) but UI claims it's off) and this makes it impossible to start urdd even if one fixes the problem (configuring and activating a usenet server). It has to be killed from the cli and this may be beyond a new user. urdd should terminate in this condition, or the web ui should show urdd in "broken" state so one can kill it from there and restart. Hinting the user towards the log in such a case would be very user friendly.

There are probably other cases where this can happen as well, such as incorrect rights settings on directories, but I haven't investigated this.

[spearhead]

I'll look into both things... thanx again

[spearhead]

but it won't be before may probably.. i usually take a small break from URD after a release...

[thorwak]

Ah! Well that makes sense. And a good way not to "burn out" on a project and loose interest. I think that is wise actually. Thanks for telling, I might have started to wonder a bit otherwise at some point

I'll report any bugs here anyway, so they are documented and I don't forget about them.


I also have a few more, partly new, ideas for implementing an archive and in a way working around the problem of mysql choking on the queries. I'll post that in that performance thread of mine. Any comments are welcome, but I won't expect anything until you feel ready to dig in again, and I'll experiment on my own meanwhile if time permits. Of course not committing any code though since it'll mostly be hacks to test ideas out.

[thorwak]

When updating a group, article count (as seen in subscribed group list) is incremented by 1 even if 0 new articles gotten.

To reproduce, subscribe to a small group and mostly inactive group (search for "swedish" for some good examples  ) and update several times after the initial header DL. For every update, article count is increased by 1 which must be a bug?

[spearhead]

I can't reproduce this. The article count is always the same. Also this number is generated by a count on the parts_XXX table... not a counter

[thorwak]

Well I don't know what to tell you.. I tried it in a couple of groups and saw the same behavior repeatedly - always increasing by exactly 1. Now it's not happening however. I guess it's possible I managed to exactly match someone posting at the exact same speed I was updating.. very very strange though, I did test many times, and also waiting sometimes between updating. I have no explanation, but trust me, I do test this kinda stuff a lot before posting something like this

I'll just have to get back about this if I can somehow figure out what was happening.

[thorwak]

Happening again right now in a.b.swebits. Doesn't matter if I wait 5 seconds or minutes between updates - always increase by exactly 1. Something is going on but I don't understand exactly what it is. (Remember to press F5 after updating...)

[spearhead]

I tried it out on several groups with or without expire afterwards, but it isn't happening here.

[thorwak]

Well I started fearing for my sanity, but it's real I waited an hour, updated - increased by 1. Waited 1 sec, updated - increased by 1. I Purged group, got everything again (730 days retention) - and there were a about 20 msgs fewer (all my "updates" gone). I started updating again, and sure enough, they started increasing, one by one. Select count(*) confirmed. And, it seems to be the very last msg that get fetched again:

Code:

mysql> select * from parts_1764 where ID > 8470;
+------+----------------------------------+-------------------------------------------------------+------------------------------------------------------------------------------------------------------------------+--------------------------+------------+------------+--------+
| ID   | binaryID                         | messageID                                             | subject                                                                                                          | fromname                 | date       | partnumber | size   |
+------+----------------------------------+-------------------------------------------------------+------------------------------------------------------------------------------------------------------------------+--------------------------+------------+------------+--------+
| 8471 | b6f10e609020890f5e8c6c7ddcf47ee9 | part24of79.npSevwBgp2Pdc1Et1VgP@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [004/112] - "changed.r01" yEnc                                     | banana@muffin.ey (Not4U) | 1263094248 |         24 | 661793 |
| 8472 | b6f10e609020890f5e8c6c7ddcf47ee9 | part25of79.npSevwBgp2Pdc1Et1VgP@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [004/112] - "changed.r01" yEnc                                     | banana@muffin.ey (Not4U) | 1263094251 |         25 | 662047 |
| 8473 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8474 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8475 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8476 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8477 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8478 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8479 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8480 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
+------+----------------------------------+-------------------------------------------------------+------------------------------------------------------------------------------------------------------------------+--------------------------+------------+------------+--------+
10 rows in set (0.00 sec)

Now, it may not be the fault of urd if you're not seeing it, could be Giganews or their proxy, but it's happening.

I'll investigate more another day.

[thorwak]

Nope, not the very last one, but one fairly close to the end repeating. It's tempting to suspect something fishy since it's msg 8000 + 1.. Isn't there something about batch getting of headers in the code? 2 or 4000 or something at a time?

Code:

mysql> select * from parts_1764 where size = 660865 and partnumber = 21;
+------+----------------------------------+-------------------------------------------------------+------------------------------------------------------------------------------------------------------------------+--------------------------+------------+------------+--------+
| ID   | binaryID                         | messageID                                             | subject                                                                                                          | fromname                 | date       | partnumber | size   |
+------+----------------------------------+-------------------------------------------------------+------------------------------------------------------------------------------------------------------------------+--------------------------+------------+------------+--------+
| 8001 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8474 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8473 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8475 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8476 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8477 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8478 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8479 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
| 8480 | 410e978866c490e4dcd507910997eeb1 | part21of24.1AqhgERRmAcb610SkVVg@powerpost2000AA.local | some.names.have.been.changed.to.protect.the-inn0cent [03/26] - "some.names.have.been.changed.to.protect.the-inn0cent.r00" yEnc | banana@muffin.ey (Not4U) | 1262884566 |         21 | 660865 |
+------+----------------------------------+-------------------------------------------------------+------------------------------------------------------------------------------------------------------------------+--------------------------+------------+------------+--------+

[spearhead]

If you switch to debug mode you see a text sth like "getting header X to Y"

if these numbers change (esp Y) it maybe giganews. Post them here and I'll have a look

[thorwak]

Log filtered on "Getting", it seems to be doing OK in the log, but the phenomenon with the "ghost article" keeps happening.

Code:

2010-04-23 10:39:05 DEBUG Getting articles 0 - 0
2010-04-23 10:38:54 DEBUG Getting articles 0 - 0
2010-04-23 10:38:51 DEBUG Getting articles 0 - 0
2010-04-23 10:38:37 DEBUG Getting articles 0 - 0

Let me know if you want complete logs (they get kinda of huge though, plenty of read line: and stuff

Edit: I guess maybe it shouldn't get articles 0 - 0 but rather skip the whole "getting" part if it's 0 - 0? I haven't looked at the code though.

[thorwak]

I always end up finding the weirdest bugs/phenomena in everything I touch, why is that?

EDIT: Remember you're on vacation! This doesn't break anything, enjoy the spring instead The bugs don't go anywhere, and this doesn't seem to break anything, just a weird "itch"

[spearhead]

I compare it with my results later...

you can minimise the status screen so that the log gets less cluttered

[thorwak]

you can minimise the status screen so that the log gets less cluttered

Good point, why didn't I think of thay myself? 

Anyway, just tell me if you need more logs if you still can't reproduce. I can filter on any keywords also if you like.

Finally, I'm using that giganews proxy program to get compressed headers (really works wonders in updating speed - I wonder if it'll run under Wine?). I'm almost 100% sure it won't change anything if I take it away, but if you can't track it down I can create a setup without this for testing.

[thorwak]

Not quite a bug, but very inappropriate  behaviour:

When set generation is in progress for a group, the pre-existing sets for that group still turn up in the set list, set searches etc. The problem is these look complete, have the right size etc in the set list, but if one downloads one of them one is very likely to end up with a broken download, often only a fraction of the entire download. This is because the download info is gathered while the set is still being re-generated. One can actually see that the size differs if one chooses "show set info" -  the size reported here is the correct "current" size, and is lower than the size showed in the set list.

Since set updating can take a long time depending on retention, one is very likely to download incomplete sets by mistake this way, especially since group name is not listed for sets in the set list (this would be a nice option btw - perhaps show in a popup while hovering on the set name?). It could also lead to creating NZB-files that are broken, and this wouldn't be noticed until trying to use them, perhaps much later, leading to some serious head scratching..

Possible solutions:

- Disable (new) downloads for groups currently generating sets (maybe just hiding them?).

- A warning and/or check if the current size differs from the stored size (in the set list) would also work.

- Generate set in a new table, leaving the existing one untouched, and then just drop the old one when it's done and replace with new one. Fanciest, and would enable downloads to work properly even while generating sets, but probably takes a lot more work; perhaps not worth it.

This may not be a problem in the future if set generation is radically changed, as discussed elsewhere in performance contexts, so that old sets are not re-generated all the time. If this is going to be implemented one can ignore this issue for now.


Note: Already started downloads are of course not affected by set generation.

Note2: I haven't tried this since pre-1.0.4, but I haven't seen any code commits that would affect this, so I'm sure it's still there.

edit: my usual typos (missing words) 

[spearhead]

Let me know if you want complete logs (they get kinda of huge though, plenty of read line: and stuff

Edit: I guess maybe it shouldn't get articles 0 - 0 but rather skip the whole "getting" part if it's 0 - 0? I haven't looked at the code though.

I made some adjustments here... pls see if the are helping

[spearhead]

- Admin's email-address is still not saved from the installation script when doing a fresh install. Download path saving works now however.

Should be fixed too

[spearhead]

- If one has an installation without any active usenet server (typical scenario after a fresh installation) and tries to start urdd, nothing (seems to) happen. In the logs, one can see that it tried to start up, and that one should activate at least one usenet server. urdd is shown as stopped. However, the process is still there (doesn't terminate itself) but UI claims it's off) and this makes it impossible to start urdd even if one fixes the problem (configuring and activating a usenet server). It has to be killed from the cli and this may be beyond a new user. urdd should terminate in this condition, or the web ui should show urdd in "broken" state so one can kill it from there and restart. Hinting the user towards the log in such a case would be very user friendly.

There are probably other cases where this can happen as well, such as incorrect rights settings on directories, but I haven't investigated this.

I'm not sure I really understand this completely. URDD should always be shutdownable from the web interface regardless of any setting (ie if you are an admin)

Anyway I'll look into posting some message or something around the usenet server config.

[thorwak]

I'm not sure I really understand this completely. URDD should always be shutdownable from the web interface regardless of any setting (ie if you are an admin)

Put shortly, urdd started up, couldn't continue properly since there was no active Usenet server configured. I guess it maybe tried to shut down here (the UI indicated it WAS off), but "ps -ef | grep php" showed it actively running. Since it was already running it couldn't be started again (new instance exited immediately). Only way to solve this was by killing it from the CLI, since UI didn't know it was running.

This seemed to happen consistently when starting urdd from the web UI with no Usenet server being active.