Article reported as posted, doesn't show up in the group

kmitko

Happens from time to time, I can't really say why. When I click "Submit post", the article is reported as posted and shows up in the "Sent" mailbox, but doesn't show up in the group. It happened to me twice on two different servers. The only thing I can spot in the log is:

[DEBUG] 09:42:34.793 | [Usenapp 1054473]Files database not found. Creating a new one.
[INFO]  09:42:34.897 | [Usenapp 612727]----------------------------------------------------------------
[INFO]  09:42:34.898 | [Usenapp 612840]Start NNTP_Post Operation for =?UTF-8?B?UmU6IFtQcmFzw7N3a2FdIFdlbnVzamHFhHNraSBmb3Nmb3Jvd29kw7Ny?=
[INFO]  09:42:34.899 | [Usenapp 612927]----------------------------------------------------------------
[DEBUG] 09:43:04.025 | [Usenapp 521794]7883966051181	 | chmurka | Inputstream | NSStreamEventEndEncountered

Andre

If you turn on the socket debugger then the log file shows hopefully more info about this.

kmitko

It looks like it happens when connection was idle for some time (I've set program to download new headers every 30 minutes):

[DEBUG] 12:06:06.908 | [Usenapp 1054473]Files database not found. Creating a new one.
[INFO]  12:06:07.010 | [Usenapp 612727]----------------------------------------------------------------
[INFO]  12:06:07.012 | [Usenapp 612840]Start NNTP_Post Operation for =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbxIXFm8SF4oiCxZvEheKIgsSFxZviiILFm+KIgsSF4oiCxZvEhcSFxZviiILFm8SF4oiCxIXFm+KIgsSFxZviiILEhcWb4oiCxIXFm+KIgsSFxZviiILEhcWb4oiCxZvEheKIgsWb4oiCxIXFm+KIgsSFxZviiILEhcWb4oiCxZvEheKIgsWbxIXiiILEhcWb4oiCxZvEheKIgsSFxZviiILFm8SF4oiC?=
[INFO]  12:06:07.013 | [Usenapp 612927]----------------------------------------------------------------
[DEBUG] 12:06:07.027 | [Usenapp 519810]1) 13114938984220	 | chmurka | 0 | sendToServer
[DEBUG] 12:06:09.348 | [Usenapp 512358]13114938984220	 | chmurka | No segments available. Socket is going into IDLE mode.
[DEBUG] 12:06:49.992 | [Usenapp 520753]0) 13114938984220	 | chmurka | 37 | NSStreamEventHasBytesAvailable
[DEBUG] 12:06:49.993 | [Usenapp 524708]13114938984220	 | chmurka | 0 | tCODE
[DEBUG] 12:06:49.994 | [Usenapp 521794]13114938984220	 | chmurka | Inputstream | NSStreamEventEndEncountered
[DEBUG] 12:06:49.995 | [Usenapp 517235]13114938984220	 | chmurka | Terminating thread
[DEBUG] 12:06:49.997 | [Usenapp 505306]13114938984220	 | chmurka | Closed socket
[DEBUG] 12:06:49.997 | [Usenapp 505306]13114938984220	 | chmurka | Closed socket
[DEBUG] 12:07:18.174 | [Usenapp 520753]0) 13114938984220	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:18.176 | [Usenapp 524295]13114938984220	 | chmurka | 0
[DEBUG] 12:07:18.176 | [Usenapp 524708]13114938984220	 | chmurka | 0 | tCODE
[DEBUG] 12:07:18.177 | [Usenapp 530248]13114938984220	 | chmurka | 200 | news.chmurka.net InterNetNews NNRP server INN 2.6.0 ready (no posting)
[DEBUG] 12:07:18.178 | [Usenapp 519810]1) 13114938984220	 | chmurka | 0 | sendToServer
[DEBUG] 12:07:18.235 | [Usenapp 520753]0) 13114938984220	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:18.237 | [Usenapp 524295]13114938984220	 | chmurka | 0
[DEBUG] 12:07:18.238 | [Usenapp 524708]13114938984220	 | chmurka | 0 | tCODE
[DEBUG] 12:07:18.240 | [Usenapp 530248]13114938984220	 | chmurka | 381 | Enter password
[DEBUG] 12:07:18.241 | [Usenapp 519810]1) 13114938984220	 | chmurka | 0 | sendToServer
[DEBUG] 12:07:18.301 | [Usenapp 520753]0) 13114938984220	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:18.302 | [Usenapp 524295]13114938984220	 | chmurka | 0
[DEBUG] 12:07:18.303 | [Usenapp 524708]13114938984220	 | chmurka | 0 | tCODE
[DEBUG] 12:07:18.305 | [Usenapp 530248]13114938984220	 | chmurka | 281 | Authentication succeeded
[DEBUG] 12:07:18.306 | [Usenapp 514423]13114938984220	 | chmurka | Server command | GROUP alt.pl.test
[DEBUG] 12:07:18.308 | [Usenapp 519810]1) 13114938984220	 | chmurka | 0 | sendToServer
[DEBUG] 12:07:18.364 | [Usenapp 520753]0) 13114938984220	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:18.365 | [Usenapp 524295]13114938984220	 | chmurka | 0
[DEBUG] 12:07:18.366 | [Usenapp 524708]13114938984220	 | chmurka | 0 | tCODE
[DEBUG] 12:07:18.367 | [Usenapp 530248]13114938984220	 | chmurka | 211 | 382 26729 27112 alt.pl.test
[DEBUG] 12:07:18.369 | [Usenapp 530593]13114938984220	 | chmurka | 211 | 382 26729 27112 alt.pl.test
[DEBUG] 12:07:18.370 | [Usenapp 512358]13114938984220	 | chmurka | No segments available. Socket is going into IDLE mode.
[DEBUG] 12:07:18.382 | [Usenapp 514423]13114938984220	 | chmurka | Server command | XOVER 27111-27112
[DEBUG] 12:07:18.383 | [Usenapp 519810]1) 13114938984220	 | chmurka | 0 | sendToServer
[DEBUG] 12:07:18.438 | [Usenapp 520753]0) 13114938984220	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:18.440 | [Usenapp 524295]13114938984220	 | chmurka | 0
[DEBUG] 12:07:18.441 | [Usenapp 524708]13114938984220	 | chmurka | 0 | tCODE
[DEBUG] 12:07:18.442 | [Usenapp 530248]13114938984220	 | chmurka | 224 | Overview information for 27111-27112 follows
[DEBUG] 12:07:18.443 | [Usenapp 534412]13114938984220	 | chmurka | 224 | Overview information for 27111-27112 follows
[DEBUG] 12:07:18.444 | [Usenapp 525163]13114938984220	 | chmurka | 0 | tDATA
[DEBUG] 12:07:18.463 | [Usenapp 512358]13114938984220	 | chmurka | No segments available. Socket is going into IDLE mode.
[DEBUG] 12:07:18.507 | [Usenapp 520753]0) 14239853837415	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:18.508 | [Usenapp 524295]14239853837415	 | chmurka | 0
[DEBUG] 12:07:18.508 | [Usenapp 524708]14239853837415	 | chmurka | 0 | tCODE
[DEBUG] 12:07:18.509 | [Usenapp 530248]14239853837415	 | chmurka | 200 | news.chmurka.net InterNetNews NNRP server INN 2.6.0 ready (no posting)
[DEBUG] 12:07:18.509 | [Usenapp 519810]1) 14239853837415	 | chmurka | 0 | sendToServer
[DEBUG] 12:07:18.566 | [Usenapp 520753]0) 14239853837415	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:18.566 | [Usenapp 524295]14239853837415	 | chmurka | 0
[DEBUG] 12:07:18.567 | [Usenapp 524708]14239853837415	 | chmurka | 0 | tCODE
[DEBUG] 12:07:18.567 | [Usenapp 530248]14239853837415	 | chmurka | 381 | Enter password
[DEBUG] 12:07:18.568 | [Usenapp 519810]1) 14239853837415	 | chmurka | 0 | sendToServer
[DEBUG] 12:07:18.625 | [Usenapp 520753]0) 14239853837415	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:18.625 | [Usenapp 524295]14239853837415	 | chmurka | 0
[DEBUG] 12:07:18.626 | [Usenapp 524708]14239853837415	 | chmurka | 0 | tCODE
[DEBUG] 12:07:18.626 | [Usenapp 530248]14239853837415	 | chmurka | 281 | Authentication succeeded
[DEBUG] 12:07:18.627 | [Usenapp 512358]14239853837415	 | chmurka | No segments available. Socket is going into IDLE mode.
[DEBUG] 12:07:24.265 | [Usenapp 514423]13114938984220	 | chmurka | Server command | ARTICLE <rjq3a9$cg3$1$kmitko@news.chmurka.net>
[DEBUG] 12:07:24.266 | [Usenapp 519810]1) 13114938984220	 | chmurka | 0 | sendToServer
[DEBUG] 12:07:24.328 | [Usenapp 520753]0) 13114938984220	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:24.329 | [Usenapp 524295]13114938984220	 | chmurka | 0
[DEBUG] 12:07:24.330 | [Usenapp 524708]13114938984220	 | chmurka | 0 | tCODE
[DEBUG] 12:07:24.332 | [Usenapp 530248]13114938984220	 | chmurka | 220 | 0 <rjq3a9$cg3$1$kmitko@news.chmurka.net> article
[DEBUG] 12:07:24.333 | [Usenapp 525163]13114938984220	 | chmurka | 0 | tDATA
[DEBUG] 12:07:24.334 | [Usenapp 520753]0) 13114938984220	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:24.335 | [Usenapp 524295]13114938984220	 | chmurka | 0
[DEBUG] 12:07:24.335 | [Usenapp 525163]13114938984220	 | chmurka | 0 | tDATA
[DEBUG] 12:07:24.340 | [Usenapp 512358]13114938984220	 | chmurka | No segments available. Socket is going into IDLE mode.
[DEBUG] 12:07:25.424 | [Usenapp 514423]13114938984220	 | chmurka | Server command | ARTICLE <rjq3bs$cg3$2$kmitko@news.chmurka.net>
[DEBUG] 12:07:25.426 | [Usenapp 519810]1) 13114938984220	 | chmurka | 0 | sendToServer
[DEBUG] 12:07:25.486 | [Usenapp 520753]0) 13114938984220	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:25.488 | [Usenapp 524295]13114938984220	 | chmurka | 0
[DEBUG] 12:07:25.489 | [Usenapp 524708]13114938984220	 | chmurka | 0 | tCODE
[DEBUG] 12:07:25.490 | [Usenapp 530248]13114938984220	 | chmurka | 220 | 0 <rjq3bs$cg3$2$kmitko@news.chmurka.net> article
[DEBUG] 12:07:25.491 | [Usenapp 525163]13114938984220	 | chmurka | 0 | tDATA
[DEBUG] 12:07:25.492 | [Usenapp 520753]0) 13114938984220	 | chmurka | 0 | NSStreamEventHasBytesAvailable
[DEBUG] 12:07:25.493 | [Usenapp 524295]13114938984220	 | chmurka | 0
[DEBUG] 12:07:25.494 | [Usenapp 525163]13114938984220	 | chmurka | 0 | tDATA
[DEBUG] 12:07:25.499 | [Usenapp 512358]13114938984220	 | chmurka | No segments available. Socket is going into IDLE mode.

Andre

kmitko It looks like it happens when connection was idle for some time (I've set program to download new headers every 30 minutes):

It all seems normal in the log file.
You posted a message at 12:06:07 and all events that follow are normal.

1) Did the posted message from 12:06:07 not get through?
2) If not, have you tried it a second time and was it successful?
3) Did you use the Followup-To textfield?
4) Can you remember if the (failed) posted message was still in the queue?
5) Did this issue started since v0.90.2 (Build 252)?

Andre

I've been walking through the source and noticed that this can happen in case the server is not responding or suddenly drops the connection.

I'll rewrite the part that is responsible for this and make it full monkey proof.

kmitko

Thanks!

kmitko

Andre

It did not get through so far.
Not with that one, but in previous case I tried second time and were succesful.
No, it was sent to a single group only.
I'm not sure, but I don't think so.
I'll check check out the new version.

Andre

I made a custom build that double checks if the message was posted.
If posting failed, a pop-up window will appear asking you to try posting again.

Can you install this custom release and see how it goes?
I am mainly interested that you will not get false reports and how it responds to the retry feature.

https://usenapp.com/download/custom/Usenapp-0.90.3.dmg

kmitko

Using the custom build, I've waited about 10 minutes after getting new headers and tried to post new message. I got dialog saying "Unable to post message". Clicking "Retry" makes posting message fail and go back to the "Unable to post message" again and again; if I cancel and write the message from scratch, it is sucessfully posted.

EDIT: Happens always if I wait too long between getting new headers and trying to post. Latest log:

[DEBUG] 15:34:50.003 | [Usenapp 1058405]Files database not found. Creating a new one.
[INFO]  15:34:50.071 | [Usenapp 615769]----------------------------------------------------------------
[INFO]  15:34:50.072 | [Usenapp 615882]Start NNTP_Post Operation for =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbIGTEhcWbw7NewqDiiILEhcWbw7NexZvEhWQgxIXFm17Ds+KIgiBzYWTDs8WbxIVeZG1zYW/iiILCoMWbwqjEhXNhIGRvxIXFm+KIgiDEhcWbXsOzZMKgxIVexZvDs2TCoMWbxIXDs15kIMSFxZvDs15kwqDEhcWbw7PiiILCoMSFxZtew7NkwqBexIXDs8Wb4oiCwqBexIXDs8WbZMKgw7PEhV7Fm2TCoMWbw7PEhV5kIMSFxZvDs17iiII=?=
[INFO]  15:34:50.073 | [Usenapp 615969]----------------------------------------------------------------
[DEBUG] 15:34:50.079 | [Usenapp 522670]1) 9442634733979	 | chmurka | 0 | sendToServer
[DEBUG] 15:34:52.693 | [Usenapp 515218]9442634733979	 | chmurka | No segments available. Socket is going into IDLE mode.
[ERROR] 15:34:52.695 | [Usenapp 631816]Posting failed for Object: =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbIGTEhcWbw7NewqDiiILEhcWbw7NexZvEhWQgxIXFm17Ds+KIgiBzYWTDs8WbxIVeZG1zYW/iiILCoMWbwqjEhXNhIGRvxIXFm+KIgiDEhcWbXsOzZMKgxIVexZvDs2TCoMWbxIXDs15kIMSFxZvDs15kwqDEhcWbw7PiiILCoMSFxZtew7NkwqBexIXDs8Wb4oiCwqBexIXDs8WbZMKgw7PEhV7Fm2TCoMWbw7PEhV5kIMSFxZvDs17iiII=?=
[INFO]  15:34:55.134 | [Usenapp 615769]----------------------------------------------------------------
[INFO]  15:34:55.136 | [Usenapp 615882]Start NNTP_Post Operation for =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbIGTEhcWbw7NewqDiiILEhcWbw7NexZvEhWQgxIXFm17Ds+KIgiBzYWTDs8WbxIVeZG1zYW/iiILCoMWbwqjEhXNhIGRvxIXFm+KIgiDEhcWbXsOzZMKgxIVexZvDs2TCoMWbxIXDs15kIMSFxZvDs15kwqDEhcWbw7PiiILCoMSFxZtew7NkwqBexIXDs8Wb4oiCwqBexIXDs8WbZMKgw7PEhV7Fm2TCoMWbw7PEhV5kIMSFxZvDs17iiII=?=
[INFO]  15:34:55.137 | [Usenapp 615969]----------------------------------------------------------------
[DEBUG] 15:34:55.142 | [Usenapp 522670]1) 9442634733979	 | chmurka | 0 | sendToServer
[DEBUG] 15:34:57.695 | [Usenapp 515218]9442634733979	 | chmurka | No segments available. Socket is going into IDLE mode.
[ERROR] 15:34:57.697 | [Usenapp 631816]Posting failed for Object: =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbIGTEhcWbw7NewqDiiILEhcWbw7NexZvEhWQgxIXFm17Ds+KIgiBzYWTDs8WbxIVeZG1zYW/iiILCoMWbwqjEhXNhIGRvxIXFm+KIgiDEhcWbXsOzZMKgxIVexZvDs2TCoMWbxIXDs15kIMSFxZvDs15kwqDEhcWbw7PiiILCoMSFxZtew7NkwqBexIXDs8Wb4oiCwqBexIXDs8WbZMKgw7PEhV7Fm2TCoMWbw7PEhV5kIMSFxZvDs17iiII=?=
[INFO]  15:34:58.964 | [Usenapp 615769]----------------------------------------------------------------
[INFO]  15:34:58.966 | [Usenapp 615882]Start NNTP_Post Operation for =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbIGTEhcWbw7NewqDiiILEhcWbw7NexZvEhWQgxIXFm17Ds+KIgiBzYWTDs8WbxIVeZG1zYW/iiILCoMWbwqjEhXNhIGRvxIXFm+KIgiDEhcWbXsOzZMKgxIVexZvDs2TCoMWbxIXDs15kIMSFxZvDs15kwqDEhcWbw7PiiILCoMSFxZtew7NkwqBexIXDs8Wb4oiCwqBexIXDs8WbZMKgw7PEhV7Fm2TCoMWbw7PEhV5kIMSFxZvDs17iiII=?=
[INFO]  15:34:58.966 | [Usenapp 615969]----------------------------------------------------------------
[DEBUG] 15:34:58.969 | [Usenapp 522670]1) 9442634733979	 | chmurka | 0 | sendToServer
[ERROR] 15:35:01.695 | [Usenapp 631816]Posting failed for Object: =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbIGTEhcWbw7NewqDiiILEhcWbw7NexZvEhWQgxIXFm17Ds+KIgiBzYWTDs8WbxIVeZG1zYW/iiILCoMWbwqjEhXNhIGRvxIXFm+KIgiDEhcWbXsOzZMKgxIVexZvDs2TCoMWbxIXDs15kIMSFxZvDs15kwqDEhcWbw7PiiILCoMSFxZtew7NkwqBexIXDs8Wb4oiCwqBexIXDs8WbZMKgw7PEhV7Fm2TCoMWbw7PEhV5kIMSFxZvDs17iiII=?=
[DEBUG] 15:35:01.695 | [Usenapp 515218]9442634733979	 | chmurka | No segments available. Socket is going into IDLE mode.
[INFO]  15:35:03.480 | [Usenapp 615769]----------------------------------------------------------------
[INFO]  15:35:03.481 | [Usenapp 615882]Start NNTP_Post Operation for =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbIGTEhcWbw7NewqDiiILEhcWbw7NexZvEhWQgxIXFm17Ds+KIgiBzYWTDs8WbxIVeZG1zYW/iiILCoMWbwqjEhXNhIGRvxIXFm+KIgiDEhcWbXsOzZMKgxIVexZvDs2TCoMWbxIXDs15kIMSFxZvDs15kwqDEhcWbw7PiiILCoMSFxZtew7NkwqBexIXDs8Wb4oiCwqBexIXDs8WbZMKgw7PEhV7Fm2TCoMWbw7PEhV5kIMSFxZvDs17iiII=?=
[INFO]  15:35:03.482 | [Usenapp 615969]----------------------------------------------------------------
[DEBUG] 15:35:03.487 | [Usenapp 522670]1) 9442634733979	 | chmurka | 0 | sendToServer
[DEBUG] 15:35:05.698 | [Usenapp 515218]9442634733979	 | chmurka | No segments available. Socket is going into IDLE mode.
[ERROR] 15:35:05.700 | [Usenapp 631816]Posting failed for Object: =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbIGTEhcWbw7NewqDiiILEhcWbw7NexZvEhWQgxIXFm17Ds+KIgiBzYWTDs8WbxIVeZG1zYW/iiILCoMWbwqjEhXNhIGRvxIXFm+KIgiDEhcWbXsOzZMKgxIVexZvDs2TCoMWbxIXDs15kIMSFxZvDs15kwqDEhcWbw7PiiILCoMSFxZtew7NkwqBexIXDs8Wb4oiCwqBexIXDs8WbZMKgw7PEhV7Fm2TCoMWbw7PEhV5kIMSFxZvDs17iiII=?=
[INFO]  15:35:07.100 | [Usenapp 615769]----------------------------------------------------------------
[INFO]  15:35:07.101 | [Usenapp 615882]Start NNTP_Post Operation for =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbIGTEhcWbw7NewqDiiILEhcWbw7NexZvEhWQgxIXFm17Ds+KIgiBzYWTDs8WbxIVeZG1zYW/iiILCoMWbwqjEhXNhIGRvxIXFm+KIgiDEhcWbXsOzZMKgxIVexZvDs2TCoMWbxIXDs15kIMSFxZvDs15kwqDEhcWbw7PiiILCoMSFxZtew7NkwqBexIXDs8Wb4oiCwqBexIXDs8WbZMKgw7PEhV7Fm2TCoMWbw7PEhV5kIMSFxZvDs17iiII=?=
[INFO]  15:35:07.102 | [Usenapp 615969]----------------------------------------------------------------
[DEBUG] 15:35:07.107 | [Usenapp 522670]1) 9442634733979	 | chmurka | 0 | sendToServer
[DEBUG] 15:35:09.696 | [Usenapp 515218]9442634733979	 | chmurka | No segments available. Socket is going into IDLE mode.
[ERROR] 15:35:09.697 | [Usenapp 631816]Posting failed for Object: =?UTF-8?B?UmU6IGFhYWHEheKIgsSFxZvEhcWbIGTEhcWbw7NewqDiiILEhcWbw7NexZvEhWQgxIXFm17Ds+KIgiBzYWTDs8WbxIVeZG1zYW/iiILCoMWbwqjEhXNhIGRvxIXFm+KIgiDEhcWbXsOzZMKgxIVexZvDs2TCoMWbxIXDs15kIMSFxZvDs15kwqDEhcWbw7PiiILCoMSFxZtew7NkwqBexIXDs8Wb4oiCwqBexIXDs8WbZMKgw7PEhV7Fm2TCoMWbw7PEhV5kIMSFxZvDs17iiII=?=

Andre

Very strange.
It looks like the message could not be loaded from the database or such thing.

I'll try something else and will contact you by email later on, if that is fine with you.

Andre

I forgot to ask, but news.chmurka.net is that you private news server?
If so, what server software are you using?

kmitko

Andre
Chmurka is a private server run by someone else, admin's contact info is here: http://chmurka.net

Andre

I am still curious if this issue has been started since the last update v0.90.2 (Build 252)?
Did you have the same issues with previous releases?

v0.90.2 (Build 252) was released yesterday.

Can you try an older version and see how it goes?
https://usenapp.com/download/Usenapp-0.90.1.dmg

kmitko

The same issue exists in the 0.90.1 build.