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 9:56
183Gabrielei'll see if i can patch send on devbase so that it always closes the port.5-Aug 9:22
182Gabrielethis basically mean that we cannot rely on the gc closing our ports.5-Aug 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 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 5:56
179CarlI think we have to move the port closer out of GC, and put it somewhere else.31-Jul 22:50
178Carl"does not expect"31-Jul 22:50
177CarlThe R2 kernel knows about GC critical secions, but... it does known expect re-entrant interpreter evaluation within those sections.31-Jul 22:49
176Gabrielei'm going to get some sleep... will check here tomorrow morning.31-Jul 22:49
175CarlThis is a dangerous condition....31-Jul 22:48
174CarlI think it may be necessary to change when it gets done.31-Jul 22:48
173Gabriele"the gc is being disabled" is something that should go in the debug log ;)31-Jul 22:45
172Carlprobably31-Jul 22:44
171Gabrielein the second run?31-Jul 22:43
170Gabrielerecycle got disabled?31-Jul 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 22:43
168Carltesting... 0:00:00.625 testing... 0:00:10.922 testing... 0:00:31.70331-Jul 22:42
167Carltiming it here...31-Jul 22:42
166Gabrielehappening at the first run here..31-Jul 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 22:39
164CarlRemoving the recycle....31-Jul 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 22:37
162CarlIt looks to me like it will take an hour....31-Jul 22:36
161Gabrielehere, it errors out within a second.31-Jul 22:36
160Carlhow many minutes does that loop take???31-Jul 22:36
159Gabrielerebol --debug or something?31-Jul 22:35
158Gabrielehmm... maybe it needs to be a CLI option?31-Jul 22:35
157CarlI can try larger loop...31-Jul 22:34
156CarlQuestion is... when should that field be checked for a filename?31-Jul 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 22:34
154Gabrieleit can be very helpful to have something like this.31-Jul 22:33
153Gabrielei think it is, debugging ports is far from easy.31-Jul 22:33
152Carlsystem/ports/debug: %debug-output.txt31-Jul 22:33
151CarlRegarding port debug... is it worth adding to system/ports object a debug field?31-Jul 22:32
150Carlnever31-Jul 22:31
149Gabrieleyou never get the error?31-Jul 22:30
148CarlRuns ok, multiple times.31-Jul 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 22:29
146Carlyes, gc disabled31-Jul 22:25
145Carlworks.31-Jul 22:24
144Carltrying it31-Jul 22:22
143Gabrielerebol just fills up your memory (gc disabled?)31-Jul 22:20
142Gabrielenotice that something strange happens if you run the loop again *after* you get that error.31-Jul 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 22:19
140Gabrielei just picked a random port id :)31-Jul 22:19
139Carlself 666?31-Jul 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 22:18
137CarlOk, ready to test.31-Jul 22:17
136CarlBecause in R2, any function arg will keep the value alive.31-Jul 22:13
135CarlYou will need to put it in a small loop... and do it a few times.31-Jul 22:12
134Gabrielebut, i cannot reproduce it.31-Jul 22:11
133Gabriele>> recycle ** Math Error: Attempt to divide by zero ** Near: 1 / 031-Jul 22:11
132Gabrielei got the error once:31-Jul 22:11
131Gabrieleso the try is working in this case?31-Jul 22:07
130Gabrielethough... if i leave the port hanging and try a recycle, i don't get any error.31-Jul 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 22:07
128Gabrieleok, let me see...31-Jul 22:02
127Carlbbs31-Jul 21:56
126CarlBut I will not attempt to fix it unless I can test it.31-Jul 21:55
125CarlThe problem that I see here is that the "try" method used by the GC is not valid.31-Jul 21:55
124CarlThe test should be just to have an error during close on a port.31-Jul 21:54
123CarlIf you can write a small test... I will make a small fix to 2.7.31-Jul 21:54
122CarlI think I found a bug.31-Jul 21:52
121Gabrieleso that it is rethrown31-Jul 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 21:47
119Gabrielebut, i would have not figured out that was happening during the gc trying to close the imap port31-Jul 21:46
118CarlHere is a puzzle: the code that calls close from the GC has a TRY wrapper on it.31-Jul 21:46
117Carlgood31-Jul 21:45
116Gabrieleyour blog is #131-Jul 21:45
115CarlIs google.it up to date on it too?31-Jul 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 21:44
113Gabrieleor you would have pointed me to it immediatly :)31-Jul 21:43
112Gabrieleport tcp://... not open, where: 'recycle, i think i would have got it.31-Jul 21:42
111Gabrieleand, with the change of reporting the actual port that is not open, the error becomes clear.31-Jul 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 21:41
109CarlChecking something...31-Jul 21:41
108Gabrielecould the GC intercept the error and change the where field to say something like 'recycle?31-Jul 21:40
107CarlIt is a problem to ignore error exceptions, because they can include any condition.31-Jul 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 21:39
105CarlWell, I am not sure if what you are suggesting is possible.31-Jul 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 21:39
103CarlAre there any triple layer ports... that you know of?31-Jul 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 21:38
101Gabrielethat would be better.31-Jul 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 21:37
99CarlHere's an idea...31-Jul 21:36
98Gabrielethat is a possibility.31-Jul 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 21:29
96CarlWhat if we provided some kind of flag to indicate that a port should not be directly GC'd?31-Jul 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 21:28
94Gabrieleagreed, but the GC would be closing any other port anyway eventually.31-Jul 21:28
93CarlWhat if...31-Jul 21:27
92CarlThe scheme might have other things it needs to do on the close, such as close a log file.31-Jul 21:27
91Gabrielethe reason there is no check, is that normally if the tcp fails, you want to get an error.31-Jul 21:27
90CarlThe problem is, I am not sure if there is any way to solve this in REBOL itself. For example...31-Jul 21:26
89Gabrielei agree the check is a good idea.31-Jul 21:26
88Gabrieleso it still happens "inside" the gc31-Jul 21:26
87CarlBut, perhaps TCP1 should do a check before assuming that TCP2 is open.31-Jul 21:26
86Gabrieleyep, but the error happens when GC attempts to close TCP131-Jul 21:25
85CarlTCP1 uses TCP2. Then GC closes TCP2 first.31-Jul 21:25
84Gabrielethere are two ports, imapcommands:// which is my low level imap handler, and the tcp:// subport it uses31-Jul 21:25
83CarlNo, I understand.31-Jul 21:25
82Gabrieleno, that's not what's happening. i'll be more clear.31-Jul 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 21:23
80Gabrieleah, well, i can describe how it works if you are interested :)31-Jul 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 21:22
78Gabrieleotherwise... the GC needs to be able to know the correct order for closing ports.31-Jul 21:22
77Gabrielewell, if the port is going to be destroyed anyway... is it critical to report errors when closing it?31-Jul 21:22
76CarlPerhaps it should be an option on the port.31-Jul 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 20:45
74Gabrieleso... there's basically all of qtask in that process.31-Jul 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 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 17:24
71CarlIt may be possible to make this debug an option that you can turn on and off.31-Jul 17:23
70CarlI think another possible solution in this area would be to just ignore CLOSE if port is already closed.31-Jul 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 17:20
68CarlAlso, it is done outside of the primary GC critical sections.31-Jul 17:19
67CarlYes, there is special protection on CLOSE when done from GC.31-Jul 17:19
66CarlOk... seems like good progress.31-Jul 17:19
65Gabrielelet me know if you also want to debug them. It is annoying but less frequent than the port issue.31-Jul 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 14:44
63Gabrielebtw, even though my main problem is now "fixed" (but see above), i'm still getting these:31-Jul 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 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 10:06
60Gabriele(maybe the gc should ignore errors when closing ports.)31-Jul 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 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 10:05
57Gabrielemaybe I've found the bug this time...31-Jul 9:45
56Gabrieleindeed, the problem still happens after i fixed that.31-Jul 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 9:28
54Gabriele(I wonder if the same thing is happening on the actual server...)31-Jul 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 9:25
52Gabrielenow, to figure out why those ports are getting collected...31-Jul 9:04
51GabrieleI guess rebol does not like getting an error during the GC run. that's why the process sometimes crashes.31-Jul 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 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 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 9:02
47Gabrieletrying the new build...31-Jul 8:55
46GabrieleI did not edit it in any way.31-Jul 8:55
45Carlhttp://www.rebol.com/article/0371.html30-Jul 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 23:19
43CarlNow prints the target, path, and local-port id.30-Jul 22:54
42CarlUpdated the exe's to print more info.30-Jul 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 22:38
40CarlGabriele, in the debug output above... did you edit that? It's not right. The #hex numbers do not agree.30-Jul 22:35
39CarlThe port dispatcher in R2 builds a fake function context in order to get to the scheme handler functions.30-Jul 22:27
38CarlAn exception, or the internal port dispatcher.30-Jul 22:26
37CarlTwo things could be causing NEAR and WHERE problems...30-Jul 22:26
36CarlEven AltME used to do that.... but I do not remember how it was fixed.30-Jul 22:25
35Carlyes, that is strange, but I've seen it many times.30-Jul 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 22:24
33Carlok. (however, I will not be here Friday.)30-Jul 22:23
32Gabrielei'm going to get some sleep now... will post my results here tomorrow.30-Jul 22:23
31Carlyes, try that.30-Jul 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 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 22:22
28Carlyou're kidding right? that would be really bad.30-Jul 22:21
27GabrieleFYI, the imap port is referenced by an object that is stored in a block, assigned to a global word.30-Jul 22:21
26Carlunused port = unreferenced port, so scheduled for gc30-Jul 22:21
25Carlyes, the imap port is gc'd30-Jul 22:19
24Carllooking...30-Jul 22:19
23Carloff phone30-Jul 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 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 22:14
20Carlstill on phone30-Jul 22:13
19Gabrielethe Near: and the Where: of the error do *not* point to my imap code, though.30-Jul 22:11
18Gabrieleso the GC is closing the IMAP port?30-Jul 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 22:10
16Gabrielegot the error, and the file says:30-Jul 22:10
15Gabrielegoing to give it a quick try...30-Jul 22:01
14Carlreleases/tests/30-Jul 22:00
13Carlwin32 and linux uploaded30-Jul 22:00
12Carlok30-Jul 21:30
11GabrieleREBOL/Command 2.7.6.4.2 (14-Mar-2008)30-Jul 21:29
10GabrieleCommand30-Jul 21:29
9Carlwhat system/product?30-Jul 21:28
8Carlyes.30-Jul 21:28
7Gabrieleok. i can only test linux with fastcgi.30-Jul 21:27
6CarlBuilding for win32 first... then Linux.30-Jul 21:27
5Gabrieledo you have the build uploaded already?30-Jul 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 21:23
3CarlShows ports opening, closing, and gc'ing.30-Jul 21:21
2CarlGenerated a build to help track down the "port none not open" bug.30-Jul 21:20
1CarlFor debugging ports.30-Jul 21:20

Return to Index Page