R2-Beta - Ports

Return to Index Page
Most recent messages (500 max) are listed first.

#UserMessageDate
184GrahamI used to see this error on Cerebrus if I left it running long enough5-Aug-08 9:56
183Gabrielei'll see if i can patch send on devbase so that it always closes the port.5-Aug-08 9:22
182Gabrielethis basically mean that we cannot rely on the gc closing our ports.5-Aug-08 9:20
181Gabrieleit may be the same problem (you get an error while sending, the port is not closed, and it gets closed in the wrong order by the GC so you get the port none not open error).5-Aug-08 9:19
180WillArpsorry if it is not related 8) I'm sending out newsletter to thousand of users and I had to patch the send function like this http://reboot.ch/rebol/sendmail.txt I did try as suggested on rebol3 world to recycle after each send but that did not work (always had port none error stuff), the patched version works no problem. Thank you!5-Aug-08 5:56
179CarlI think we have to move the port closer out of GC, and put it somewhere else.31-Jul-08 22:50
178Carl"does not expect"31-Jul-08 22:50
177CarlThe R2 kernel knows about GC critical secions, but... it does known expect re-entrant interpreter evaluation within those sections.31-Jul-08 22:49
176Gabrielei'm going to get some sleep... will check here tomorrow morning.31-Jul-08 22:49
175CarlThis is a dangerous condition....31-Jul-08 22:48
174CarlI think it may be necessary to change when it gets done.31-Jul-08 22:48
173Gabriele"the gc is being disabled" is something that should go in the debug log ;)31-Jul-08 22:45
172Carlprobably31-Jul-08 22:44
171Gabrielein the second run?31-Jul-08 22:43
170Gabrielerecycle got disabled?31-Jul-08 22:43
169CarlIf I run it again.... >> test testing... 0:00:00.5 testing... 0:00:00.515 testing... 0:00:00.516 testing... 0:00:00.51631-Jul-08 22:43
168Carltesting... 0:00:00.625 testing... 0:00:10.922 testing... 0:00:31.70331-Jul-08 22:42
167Carltiming it here...31-Jul-08 22:42
166Gabrielehappening at the first run here..31-Jul-08 22:40
165Gabriele>> s: now/precise loop 100 [b: clear [] loop 10000 [append b open/direct test://localhost] print difference now/precise s recycle] 0:00:00.358162 ** Math Error: Attempt to divide by zero ** Near: 1 / 031-Jul-08 22:39
164CarlRemoving the recycle....31-Jul-08 22:37
163Gabrieleif i try to run it again after the error, i have to kill the rebol process because it eats all my ram.31-Jul-08 22:37
162CarlIt looks to me like it will take an hour....31-Jul-08 22:36
161Gabrielehere, it errors out within a second.31-Jul-08 22:36
160Carlhow many minutes does that loop take???31-Jul-08 22:36
159Gabrielerebol --debug or something?31-Jul-08 22:35
158Gabrielehmm... maybe it needs to be a CLI option?31-Jul-08 22:35
157CarlI can try larger loop...31-Jul-08 22:34
156CarlQuestion is... when should that field be checked for a filename?31-Jul-08 22:34
155Gabrieledid you try to increase the loops? i was using 100 and 10000 because the error seems very random... but i get it always with those numbers.31-Jul-08 22:34
154Gabrieleit can be very helpful to have something like this.31-Jul-08 22:33
153Gabrielei think it is, debugging ports is far from easy.31-Jul-08 22:33
152Carlsystem/ports/debug: %debug-output.txt31-Jul-08 22:33
151CarlRegarding port debug... is it worth adding to system/ports object a debug field?31-Jul-08 22:32
150Carlnever31-Jul-08 22:31
149Gabrieleyou never get the error?31-Jul-08 22:30
148CarlRuns ok, multiple times.31-Jul-08 22:29
147Carlmake root-protocol [ open: func [port] [port] close: func [port] [1 / 0] net-utils/net-install 'test self 666 ]

test: does [ loop 10 [ b: clear [] loop 10 [append b open/direct test://localhost] recycle ] print read %gc-port-debug.txt ]

31-Jul-08 22:29
146Carlyes, gc disabled31-Jul-08 22:25
145Carlworks.31-Jul-08 22:24
144Carltrying it31-Jul-08 22:22
143Gabrielerebol just fills up your memory (gc disabled?)31-Jul-08 22:20
142Gabrielenotice that something strange happens if you run the loop again *after* you get that error.31-Jul-08 22:20
141Gabriele>> make root-protocol [open: func [port] [port] close: func [port] [1 / 0] net-utils/net-install 'test self 666] test protocol loaded >> loop 100 [b: clear [] loop 10000 [append b open/direct test://localhost] recycle] ** Math Error: Attempt to divide by zero ** Near: 1 / 031-Jul-08 22:19
140Gabrielei just picked a random port id :)31-Jul-08 22:19
139Carlself 666?31-Jul-08 22:18
138Gabrielei've got it to max my memory, killed it just before it would crash my system... let me try again...31-Jul-08 22:18
137CarlOk, ready to test.31-Jul-08 22:17
136CarlBecause in R2, any function arg will keep the value alive.31-Jul-08 22:13
135CarlYou will need to put it in a small loop... and do it a few times.31-Jul-08 22:12
134Gabrielebut, i cannot reproduce it.31-Jul-08 22:11
133Gabriele>> recycle ** Math Error: Attempt to divide by zero ** Near: 1 / 031-Jul-08 22:11
132Gabrielei got the error once:31-Jul-08 22:11
131Gabrieleso the try is working in this case?31-Jul-08 22:07
130Gabrielethough... if i leave the port hanging and try a recycle, i don't get any error.31-Jul-08 22:07
129Gabriele>> make root-protocol [open: func [port] [port] close: func [port] [1 / 0] net-utils/net-install 'test self 666] test protocol loaded >> p: open/direct test://localhost >> close p ** Math Error: Attempt to divide by zero ** Near: 1 / 031-Jul-08 22:07
128Gabrieleok, let me see...31-Jul-08 22:02
127Carlbbs31-Jul-08 21:56
126CarlBut I will not attempt to fix it unless I can test it.31-Jul-08 21:55
125CarlThe problem that I see here is that the "try" method used by the GC is not valid.31-Jul-08 21:55
124CarlThe test should be just to have an error during close on a port.31-Jul-08 21:54
123CarlIf you can write a small test... I will make a small fix to 2.7.31-Jul-08 21:54
122CarlI think I found a bug.31-Jul-08 21:52
121Gabrieleso that it is rethrown31-Jul-08 21:47
120Gabrielehmm, i don't know how things are on the C side, but maybe the error returned by try is getting evaluated in some way?31-Jul-08 21:47
119Gabrielebut, i would have not figured out that was happening during the gc trying to close the imap port31-Jul-08 21:46
118CarlHere is a puzzle: the code that calls close from the GC has a TRY wrapper on it.31-Jul-08 21:46
117Carlgood31-Jul-08 21:45
116Gabrieleyour blog is #131-Jul-08 21:45
115CarlIs google.it up to date on it too?31-Jul-08 21:44
114CarlWell, today if you google port none not open (at least in US) you will get, at the top, the explanation.31-Jul-08 21:44
113Gabrieleor you would have pointed me to it immediatly :)31-Jul-08 21:43
112Gabrieleport tcp://... not open, where: 'recycle, i think i would have got it.31-Jul-08 21:42
111Gabrieleand, with the change of reporting the actual port that is not open, the error becomes clear.31-Jul-08 21:42
110Gabrieleif i had got: port none not open, near: rejoin [...] where: 'recycle i would have had a hint. (though i guess i would have not understood the problem anyway... but at least we can blog about it and people can search for error during recycle)31-Jul-08 21:41
109CarlChecking something...31-Jul-08 21:41
108Gabrielecould the GC intercept the error and change the where field to say something like 'recycle?31-Jul-08 21:40
107CarlIt is a problem to ignore error exceptions, because they can include any condition.31-Jul-08 21:40
106Gabrielenot that i know of, but imap:// could very well be based over imapcommands:// in principle. i don't think there are any yet though.31-Jul-08 21:39
105CarlWell, I am not sure if what you are suggesting is possible.31-Jul-08 21:39
104Gabrielei think i've learned my lesson now, and will keep an eye on this kind of problem in the future... but, what about others? :)31-Jul-08 21:39
103CarlAre there any triple layer ports... that you know of?31-Jul-08 21:38
102Gabrielei'm still concerned about there being other cases where there is an error, and the user is left puzzled as to what is really happening.31-Jul-08 21:38
101Gabrielethat would be better.31-Jul-08 21:37
100CarlWhat if the port sweep has 2 phases? The first pass only closes ports that have subports. The second pass closes all remaining ports.31-Jul-08 21:37
99CarlHere's an idea...31-Jul-08 21:36
98Gabrielethat is a possibility.31-Jul-08 21:29
97Gabrieleit is a problematic situation one should not get into, by not letting those port being collected (and that was my bug), but then maybe we should throw an error message that does not get people confused (that port not open with the weird Near: got me completely off track)31-Jul-08 21:29
96CarlWhat if we provided some kind of flag to indicate that a port should not be directly GC'd?31-Jul-08 21:29
95Gabrieleand, like in this case, the port cannot actually shut down the communication correctly, because the tcp port has already been closed.31-Jul-08 21:28
94Gabrieleagreed, but the GC would be closing any other port anyway eventually.31-Jul-08 21:28
93CarlWhat if...31-Jul-08 21:27
92CarlThe scheme might have other things it needs to do on the close, such as close a log file.31-Jul-08 21:27
91Gabrielethe reason there is no check, is that normally if the tcp fails, you want to get an error.31-Jul-08 21:27
90CarlThe problem is, I am not sure if there is any way to solve this in REBOL itself. For example...31-Jul-08 21:26
89Gabrielei agree the check is a good idea.31-Jul-08 21:26
88Gabrieleso it still happens "inside" the gc31-Jul-08 21:26
87CarlBut, perhaps TCP1 should do a check before assuming that TCP2 is open.31-Jul-08 21:26
86Gabrieleyep, but the error happens when GC attempts to close TCP131-Jul-08 21:25
85CarlTCP1 uses TCP2. Then GC closes TCP2 first.31-Jul-08 21:25
84Gabrielethere are two ports, imapcommands:// which is my low level imap handler, and the tcp:// subport it uses31-Jul-08 21:25
83CarlNo, I understand.31-Jul-08 21:25
82Gabrieleno, that's not what's happening. i'll be more clear.31-Jul-08 21:25
81CarlRegarding GC on ports... the error does not come from the GC. It comes from the usage of the port after the GC closes it.31-Jul-08 21:23
80Gabrieleah, well, i can describe how it works if you are interested :)31-Jul-08 21:23
79CarlAlso, I don't understand the comment above about blowdart. One would expect that the fastcgi process itself should be serving your web interface only, with messages sent to various sub-service handlers, such as the IMAP server. But, then, I'm not the architect of QTask (nor do I know anything about its design.)31-Jul-08 21:22
78Gabrieleotherwise... the GC needs to be able to know the correct order for closing ports.31-Jul-08 21:22
77Gabrielewell, if the port is going to be destroyed anyway... is it critical to report errors when closing it?31-Jul-08 21:22
76CarlPerhaps it should be an option on the port.31-Jul-08 21:20
75Gabrieleis it difficult to make it so errors during the GC run are reported in a way that it is obvious what's going on? otherwise i'd really prefer to have them ignored.31-Jul-08 20:45
74Gabrieleso... there's basically all of qtask in that process.31-Jul-08 20:39
73Gabrielei don't know if it's only in fastcgi, i'd need to come up with some kind of test outside of fastcgi, but it's not easy because blowdart is the API interface to Qtask31-Jul-08 20:39
72CarlThe internal error above is very serious... and we must be able to easily reproduce it to find the problem. Is it only in FastCGI?31-Jul-08 17:24
71CarlIt may be possible to make this debug an option that you can turn on and off.31-Jul-08 17:23
70CarlI think another possible solution in this area would be to just ignore CLOSE if port is already closed.31-Jul-08 17:21
69CarlDuring GC we simply build a list of ports that need to be closed, then we finish the GC and close the ports. The ports themselves will not b GC'd until the *next* GC recycle.31-Jul-08 17:20
68CarlAlso, it is done outside of the primary GC critical sections.31-Jul-08 17:19
67CarlYes, there is special protection on CLOSE when done from GC.31-Jul-08 17:19
66CarlOk... seems like good progress.31-Jul-08 17:19
65Gabrielelet me know if you also want to debug them. It is annoying but less frequent than the port issue.31-Jul-08 14:45
64Gabriele[Thu Jul 31 16:40:22 2008] [warn] FastCGI: (dynamic) server "/home/giesse/Qtask/Mercurial/qtask/rootdocs/blowdart.fcgi" (pid 15182) terminated by calling exit with status '50' [Thu Jul 31 16:40:30 2008] [warn] FastCGI: (dynamic) server "/home/giesse/Qtask/Mercurial/qtask/rootdocs/blowdart.fcgi" restarted (pid 15362) REBOL Internal Error: Invalid series width 1 was 16 (type 39)

Program terminated abnormally. This should never happen. Contact www.REBOL.com with details. [Thu Jul 31 16:40:46 2008] [warn] FastCGI: (dynamic) server "/home/giesse/Qtask/Mercurial/qtask/rootdocs/blowdart.fcgi" (pid 15258) terminated by calling exit with status '50'

31-Jul-08 14:44
63Gabrielebtw, even though my main problem is now "fixed" (but see above), i'm still getting these:31-Jul-08 14:44
62Gabrieleso my conclusion is... 1) the gc should ignore errors, or report them in a special way so that we know what's really happening 2) it would be useful to have a debug version of rebol that prints to a file like this. i would not have guessed what was happening here.31-Jul-08 10:08
61Gabrielethe other typo was causing the port being closed when it wasn't supposed to (and because of the first typo, it was not closed correctly)31-Jul-08 10:06
60Gabriele(maybe the gc should ignore errors when closing ports.)31-Jul-08 10:06
59Gabrieleone typo was preventing the port being closed, so it ended up being closed by the gc eventually, and in the wrong order (tcp first)31-Jul-08 10:05
58Gabrieleok, I had TWO typos in my code that, together, created this problem. :) still testing to make sure it works now...31-Jul-08 10:05
57Gabrielemaybe I've found the bug this time...31-Jul-08 9:45
56Gabrieleindeed, the problem still happens after i fixed that.31-Jul-08 9:28
55Gabriele(i wonder why it doesn't happen more often though if that is the case. it should find more than one port hanging.)31-Jul-08 9:28
54Gabriele(I wonder if the same thing is happening on the actual server...)31-Jul-08 9:26
53Gabrieleah, maybe I had a bug in the stress test script that i was using that caused those ports to be GCed. doing more testing...31-Jul-08 9:25
52Gabrielenow, to figure out why those ports are getting collected...31-Jul-08 9:04
51GabrieleI guess rebol does not like getting an error during the GC run. that's why the process sometimes crashes.31-Jul-08 9:04
50Gabrielei guess that since this is happening during a gc run, the Near is being set to the code that was running when the GC run happened, which explains what I am seeing.31-Jul-08 9:03
49Gabrieleso, what happens is, that the GC is closing the TCP port first, then the IMAP port, which relies on it. So, when the IMAP port gets closed, it tries to send the quit command to the imap server, and there is an error.31-Jul-08 9:03
48GabrieleGC : marking ports... GC : unused port : #087e6a90, tcp://pop.tiscali.it:143 local:40115 GC : unused port : #08ff3f60, imapcommands://pop.tiscali.it:143 GC : sweeping ports... GC : forced close: #087e6a90, tcp://pop.tiscali.it:143 local:40115 PORT: closed port : #087e6a90, tcp://pop.tiscali.it:143 local:40115 GC : forced close: #08ff3f60, imapcommands://pop.tiscali.it:143 ERROR: port not open: #087e6a90, tcp://pop.tiscali.it:143 local:40115 PORT: closed port : #090bfe98, tcp://:0 local:12150 PORT: closed port : #08eccd10, fastcgi://31-Jul-08 9:02
47Gabrieletrying the new build...31-Jul-08 8:55
46GabrieleI did not edit it in any way.31-Jul-08 8:55
45Carlhttp://www.rebol.com/article/0371.html30-Jul-08 23:54
44CarlAdded better error msg:

>> close a: open tcp://hq.rebol.net:80 >> copy a ** Access Error: Port tcp://hq.rebol.net:80 not open ** Near: copy a

30-Jul-08 23:19
43CarlNow prints the target, path, and local-port id.30-Jul-08 22:54
42CarlUpdated the exe's to print more info.30-Jul-08 22:52
41CarlAlso, for every line like: GC : forced close: #09080a28, imapcommands://pop.tiscali.it:143

There should be a "closed port" line for that same port following it. If not, then the port errored out during the close.

30-Jul-08 22:38
40CarlGabriele, in the debug output above... did you edit that? It's not right. The #hex numbers do not agree.30-Jul-08 22:35
39CarlThe port dispatcher in R2 builds a fake function context in order to get to the scheme handler functions.30-Jul-08 22:27
38CarlAn exception, or the internal port dispatcher.30-Jul-08 22:26
37CarlTwo things could be causing NEAR and WHERE problems...30-Jul-08 22:26
36CarlEven AltME used to do that.... but I do not remember how it was fixed.30-Jul-08 22:25
35Carlyes, that is strange, but I've seen it many times.30-Jul-08 22:25
34Gabrielealso i wonder why Near: and Where: are what they are. there is no port code in Near and I have no confirm in my IMAP code IIRC (but maybe I'm calling it in some case, i need to recheck, this was many months ago :)30-Jul-08 22:24
33Carlok. (however, I will not be here Friday.)30-Jul-08 22:23
32Gabrielei'm going to get some sleep now... will post my results here tomorrow.30-Jul-08 22:23
31Carlyes, try that.30-Jul-08 22:23
30GabrieleI will add some debugging output to my code so that we can verify whether the port is still referenced or not.30-Jul-08 22:22
29Gabrielewhen that object is removed from that block, CLOSE is called on the port, so I don't think it has been removed at that point.30-Jul-08 22:22
28Carlyou're kidding right? that would be really bad.30-Jul-08 22:21
27GabrieleFYI, the imap port is referenced by an object that is stored in a block, assigned to a global word.30-Jul-08 22:21
26Carlunused port = unreferenced port, so scheduled for gc30-Jul-08 22:21
25Carlyes, the imap port is gc'd30-Jul-08 22:19
24Carllooking...30-Jul-08 22:19
23Carloff phone30-Jul-08 22:18
22GabrieleI will do more tests tomorrow. How do you think we should proceed from here? maybe we can add more output when the error happens? printing the port # and url so that we can confirm it is the imap one.30-Jul-08 22:16
21GabrielePORT: opened port : #090b4600, file://:0 PORT: closed port : #090b4600, file://:0 PORT: opened port : #0909c530, tcp://pop.tiscali.it:143 PORT: opened port : #08fe0ea8, imapcommands://pop.tiscali.it:143 GC : marking ports... GC : unused port : #09083638, tcp://pop.tiscali.it:143 GC : unused port : #09080a28, imapcommands://pop.tiscali.it:143 GC : sweeping ports... GC : forced close: #09083638, tcp://pop.tiscali.it:143 PORT: closed port : #09083638, tcp://pop.tiscali.it:143 GC : forced close: #09080a28, imapcommands://pop.tiscali.it:143 PORT: closed port : #091c19d8, tcp://:0 PORT: closed port : #08f99f40, fastcgi://:030-Jul-08 22:14
20Carlstill on phone30-Jul-08 22:13
19Gabrielethe Near: and the Where: of the error do *not* point to my imap code, though.30-Jul-08 22:11
18Gabrieleso the GC is closing the IMAP port?30-Jul-08 22:10
17GabrielePORT: opened port : #09083638, file://:0 PORT: closed port : #09083638, file://:0 GC : marking ports... GC : unused port : #08804de0, tcp://pop.tiscali.it:143 GC : unused port : #088049e0, imapcommands://pop.tiscali.it:143 GC : sweeping ports... GC : forced close: #08804de0, tcp://pop.tiscali.it:143 PORT: closed port : #08804de0, tcp://pop.tiscali.it:143 GC : forced close: #088049e0, imapcommands://pop.tiscali.it:143 PORT: closed port : #08563890, tcp://:0 PORT: closed port : #0908daa8, fastcgi://:030-Jul-08 22:10
16Gabrielegot the error, and the file says:30-Jul-08 22:10
15Gabrielegoing to give it a quick try...30-Jul-08 22:01
14Carlreleases/tests/30-Jul-08 22:00
13Carlwin32 and linux uploaded30-Jul-08 22:00
12Carlok30-Jul-08 21:30
11GabrieleREBOL/Command 2.7.6.4.2 (14-Mar-2008)30-Jul-08 21:29
10GabrieleCommand30-Jul-08 21:29
9Carlwhat system/product?30-Jul-08 21:28
8Carlyes.30-Jul-08 21:28
7Gabrieleok. i can only test linux with fastcgi.30-Jul-08 21:27
6CarlBuilding for win32 first... then Linux.30-Jul-08 21:27
5Gabrieledo you have the build uploaded already?30-Jul-08 21:26
4CarlExample session... looping 3 times with OPEN tcp://www.rebol.net...

Output is written to gc-port-debug.txt:

GC : marking ports... GC : sweeping ports... GC : done... PORT: opened port : #0135f150, event://:0 PORT: opened port : #0135fd50, system://:0 PORT: opened port : #01360d50, file://:0 PORT: closed port : #01360d50, file://:0 PORT: opened port : #01370eb0, file://:0 PORT: closed port : #01370eb0, file://:0 PORT: opened port : #013716b0, tcp://www.rebol.net:80 PORT: opened port : #01371ab0, tcp://www.rebol.net:80 PORT: opened port : #01371eb0, tcp://www.rebol.net:80 GC : marking ports... GC : unused port : #013716b0, tcp://www.rebol.net:80 GC : unused port : #01371ab0, tcp://www.rebol.net:80 GC : sweeping ports... GC : forced close: #013716b0, tcp://www.rebol.net:80 PORT: closed port : #013716b0, tcp://www.rebol.net:80 GC : forced close: #01371ab0, tcp://www.rebol.net:80 PORT: closed port : #01371ab0, tcp://www.rebol.net:80 GC : done... PORT: closed port : #01371eb0, tcp://www.rebol.net:80 PORT: closed port : #0135fd50, system://:0 PORT: closed port : #0135f150, event://:0 REBOL terminated

30-Jul-08 21:23
3CarlShows ports opening, closing, and gc'ing.30-Jul-08 21:21
2CarlGenerated a build to help track down the "port none not open" bug.30-Jul-08 21:20
1CarlFor debugging ports.30-Jul-08 21:20

Return to Index Page