Reading froms socket: read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer about dovecot-xaps-daemon HOT 45 CLOSED

Is this caused by the previous post about production? Is it a matter of downloading and rebuilding?

from dovecot-xaps-daemon.

Saw something which may help explain
CentOS 6:
Received request: NOTIFY dovecot-username="xxx.xxx" dovecot-mailbox="INBOX"

CentOS 7:
Received request: NOTIFY dovecot-username="xxx.xxx"#011dovecot-mailbox="INBOX"

I wonder if the #011 is what is causing it. Where would that come from?

from dovecot-xaps-daemon.

The CentOS 6 plugins will not work on CentOS 7 so I looked at xaps-plugin.c like 93 there is:
str_append(req, "\tdovecot-mailbox=");
The #011 is coming from the \t. Does the protocol call for a tab or can it be a space?

from dovecot-xaps-daemon.

That just controls how it appears in the logs... Bummer. Time to keep looking.

from dovecot-xaps-daemon.

[DEBUG] NOTIFY dovecot-username="xxx.xxx" dovecot-mailbox="INBOX"
[DEBUG] Returning failure: Missing dovecot-mailbox argument

Perhaps the \t is the cause?

from dovecot-xaps-daemon.

Yes, it seems that in xapsd.go there is a problem at the function parseCommand because it's looking for \t and it finds #011. So, either the plugin is encoding it wrong or it's Go that is decoding it incorrectly. I don't know how to tell.

from dovecot-xaps-daemon.

As a temporary workaround I just used 4 spaces and in the plugin and in the daemon look for 4 spaces. It still fails with the socket error
[DEBUG] Returning success:
Reading froms socket: read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer

from dovecot-xaps-daemon.

In handleRequest I get the that socket error
if err := scanner.Err(); err != nil { log.Println("Reading from socket: ", err) }

from dovecot-xaps-daemon.

I temporarily worked around the \t delimiter issue being encoded to #011 by using a pipe in both plugins and in the daemon's parser. I just couldn't find an answer for that encoding reason. I can't tell if it's coming from the plugin or an issue with the logging in xapsd. Forcing the phone to re-register is allowing the push notiifications to come through but the code above from handleRequest is causing the error. I don't know what to do with that. So, two issues - error trapping and the \t delimiters. Eagerly awaiting Stefan's answer.

from dovecot-xaps-daemon.

Adding $EscapeControlCharactersOnReceive off and then systemctl restart rsyslog fixes the issue but I'm trying to see if there's a way to not set that globally perhaps by an /etc/rsyslog.d/xapsd.conf file of some sort.

from dovecot-xaps-daemon.

While waiting for @st3fan to respond, I came up with this. SEEMS to work. It will toggle the $EscapeControlCharactersOnReceive off depending on the logging action. Create a file /etc/rsyslog.d/xapsd-rsyslog.conf and paste in the following on one line:
if ( $programname startswith "xapsd" ) then $EscapeControlCharactersOnReceive off else $EscapeControlCharactersOnReceive on then do a systemctl restart rsyslog. This should get rid of those ugly #011 messages in the log which made me waste HOURS today. I just can't figure out what is up with the read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer error. There has to be something funky in the way the socket is handled on CentOS 7.

from dovecot-xaps-daemon.

I’ll install CentOS 7 in a VM to take a look.

I think the #11 is a red herring. I think that is just your logger that is properly escaping control characters.

What version of Dovecot does CentOS 7 have? I don’t know if my code is compatible with anything newer than what I originally wrote it for.

from dovecot-xaps-daemon.

CentOS 7 has dovecot 2.2.10. Everything builds fine. It's just the daemon with the issue. I know that I put a lot above but I can tell you that it doesn't seem to be the plugin. Reread all above and you'll see how I narrowed it down.

from dovecot-xaps-daemon.

Do you need access to a test environment?

from dovecot-xaps-daemon.

Sorry I have just been very busy with work.

My first thought: Is /var/run/xapsd/xapsd.sock accessible by Dovecot? Does it run in a chrooted env? Does that file need to be somewhere else?

from dovecot-xaps-daemon.

The sock should be accessible. It is on CentOS 6. I'm not really sure how to tell. As far as chrooted, I don't believe it is. Looking at /usr/lib/systemd/system/dovecot.service I don't see anything that indicates that. The only thing I can think of is if either dovecot or xapsd is looking in /tmp. Under CentOS 7 there are private temps now. In that file you have PrivateTmp=true. I know that has to be changed to false on Apache when running certain middlewares that get files from Apache passing off upload files to the middleware daemon via /tmp. I don't see any errors in the /var/log/messages from dovecot or xapsd saying it can't read any socket. I have xapsd running as root on CentOS 6 but under 7 it runs as it's own user. Shall I try changing that? I see from the terminal dovecot runs as root.
root 2837 0.0 0.0 15640 1484 ? Ss Jul16 0:10 /usr/sbin/dovecot -F
Want me to test a custom plugin and/or daemon to check for this?

from dovecot-xaps-daemon.

Despite those processes having access to the sock the error still occurs. What else should we check to resolve this? Perhaps a debug build?

from dovecot-xaps-daemon.

@SteffanCline Could you please provide the xapsd logs? Thanks

from dovecot-xaps-daemon.

Snippet below:

Sep  6 05:45:10 xxxxxx xapsd: 2017/09/06 05:45:10 [DEBUG] Accepted a connection
Sep  6 05:45:10 xxxxxx xapsd: 2017/09/06 05:45:10 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 05:45:10 xxxxxx xapsd: 2017/09/06 05:45:10 [DEBUG] Returning success:
Sep  6 05:45:10 xxxxxx xapsd: 2017/09/06 05:45:10 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer
Sep  6 05:50:19 xxxxxx xapsd: 2017/09/06 05:50:19 [DEBUG] Accepted a connection
Sep  6 05:50:19 xxxxxx xapsd: 2017/09/06 05:50:19 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 05:50:19 xxxxxx xapsd: 2017/09/06 05:50:19 [DEBUG] Returning success:
Sep  6 05:50:19 xxxxxx xapsd: 2017/09/06 05:50:19 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer
Sep  6 05:55:22 xxxxxx xapsd: 2017/09/06 05:55:22 [DEBUG] Accepted a connection
Sep  6 05:55:22 xxxxxx xapsd: 2017/09/06 05:55:22 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 05:55:22 xxxxxx xapsd: 2017/09/06 05:55:22 [DEBUG] Returning success:
Sep  6 05:55:22 xxxxxx xapsd: 2017/09/06 05:55:22 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer
Sep  6 06:00:24 xxxxxx xapsd: 2017/09/06 06:00:24 [DEBUG] Accepted a connection
Sep  6 06:00:24 xxxxxx xapsd: 2017/09/06 06:00:24 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 06:00:24 xxxxxx xapsd: 2017/09/06 06:00:24 [DEBUG] Returning success:
Sep  6 06:00:24 xxxxxx xapsd: 2017/09/06 06:00:24 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer
Sep  6 06:05:27 xxxxxx xapsd: 2017/09/06 06:05:27 [DEBUG] Accepted a connection
Sep  6 06:05:27 xxxxxx xapsd: 2017/09/06 06:05:27 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 06:05:27 xxxxxx xapsd: 2017/09/06 06:05:27 [DEBUG] Returning success:
Sep  6 06:05:27 xxxxxx xapsd: 2017/09/06 06:05:27 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer
Sep  6 06:10:14 xxxxxx xapsd: 2017/09/06 06:10:14 [DEBUG] Accepted a connection
Sep  6 06:10:14 xxxxxx xapsd: 2017/09/06 06:10:14 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 06:10:14 xxxxxx xapsd: 2017/09/06 06:10:14 [DEBUG] Returning success:
Sep  6 06:10:14 xxxxxx xapsd: 2017/09/06 06:10:14 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer
Sep  6 06:15:12 xxxxxx xapsd: 2017/09/06 06:15:12 [DEBUG] Accepted a connection
Sep  6 06:15:12 xxxxxx xapsd: 2017/09/06 06:15:12 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 06:15:12 xxxxxx xapsd: 2017/09/06 06:15:12 [DEBUG] Returning success:
Sep  6 06:15:12 xxxxxx xapsd: 2017/09/06 06:15:12 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer
Sep  6 06:20:16 xxxxxx xapsd: 2017/09/06 06:20:16 [DEBUG] Accepted a connection
Sep  6 06:20:16 xxxxxx xapsd: 2017/09/06 06:20:16 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 06:20:16 xxxxxx xapsd: 2017/09/06 06:20:16 [DEBUG] Returning success:
Sep  6 06:20:16 xxxxxx xapsd: 2017/09/06 06:20:16 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer
Sep  6 06:25:08 xxxxxx xapsd: 2017/09/06 06:25:08 [DEBUG] Accepted a connection
Sep  6 06:25:08 xxxxxx xapsd: 2017/09/06 06:25:08 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 06:25:08 xxxxxx xapsd: 2017/09/06 06:25:08 [DEBUG] Returning success:
Sep  6 06:25:08 xxxxxx xapsd: 2017/09/06 06:25:08 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer
Sep  6 06:30:15 xxxxxx xapsd: 2017/09/06 06:30:15 [DEBUG] Accepted a connection
Sep  6 06:30:15 xxxxxx xapsd: 2017/09/06 06:30:15 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 06:30:15 xxxxxx xapsd: 2017/09/06 06:30:15 [DEBUG] Returning success:
Sep  6 06:30:15 xxxxxx xapsd: 2017/09/06 06:30:15 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer
Sep  6 06:35:16 xxxxxx xapsd: 2017/09/06 06:35:16 [DEBUG] Accepted a connection
Sep  6 06:35:16 xxxxxx xapsd: 2017/09/06 06:35:16 [DEBUG] Received request: NOTIFY dovecot-username="camhvalues"dovecot-mailbox="INBOX"
Sep  6 06:35:16 xxxxxx xapsd: 2017/09/06 06:35:16 [DEBUG] Returning success:
Sep  6 06:35:16 xxxxxx xapsd: 2017/09/06 06:35:16 Reading from socket after handler:  read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer

from dovecot-xaps-daemon.

Which go version to you use to build the daemon?

from dovecot-xaps-daemon.

I'm no Go pro but I downloaded the latest version at the time I built it which looks to be back on July 7, 2017. According to the VERSION file it's go1.6.3

from dovecot-xaps-daemon.

You had me thinking so I downloaded Go 1.9 and rebuilt it. No change.

from dovecot-xaps-daemon.

Also tried moving the sock from /var/run/xapsd/xapsd.sock to /tmp/xapsd.sock. No change. Same reset error.

from dovecot-xaps-daemon.

I think I have it narrowed down to this section of code but I'm no Go pro. I added a string to the Success message after notify. It's when the notify finishes and comes back to here it hits the scanner error if err := scanner.Err(); err != nil. I'm reading up to see if I can get anywhere while waiting on @st3fan

func handleRequest(conn net.Conn, client *apns.Client, db *Database, topic string) {
	defer conn.Close()

	scanner := bufio.NewScanner(conn)
	for scanner.Scan() {
		if *debug {
			log.Println("[DEBUG] Received request:", scanner.Text())
		}

		command, err := parseCommand(scanner.Text())
		if err != nil {
			log.Println("Reading froms socket: ", err)
		}

		switch command.name {
		case "REGISTER":
			handleRegister(conn, command, client, db, topic)
		case "NOTIFY":
			handleNotify(conn, command, client, db)
		default:
			writeError(conn, "Unknown command")
		}
	}

	if err := scanner.Err(); err != nil {
		log.Println("Reading from socket: ", err)
	}
}

from dovecot-xaps-daemon.

Ok. Found what causes the socket to close. When it writes a success or error to the conn, it gets that error. conn.Write([]byte("OK" + " " + msg + "\n")) Now to find out why that happens. Commenting out the response back to the socket stops the error but doubt that's the solution. Now to dig further. I'm sure @st3fan will know when he gets a chance to look.

from dovecot-xaps-daemon.

Perhaps I need sleep but looking at the plugin code, its working as it should be...

      ret = net_receive(fd, res, sizeof(res)-1);
      if (ret < 0) {
        i_error("read(%s) failed: %m", socket_path);
      } else {
        res[ret] = '\0';
        if (strncmp(res, "OK ", 3) == 0) {
          ret = 0;
        }
      }

It sees the string begins with OK so it closes the connection. It shouldn't return an error because it should be seeing an EOF. Not sure how to tell that.

from dovecot-xaps-daemon.

I can't do anymore tonight. Seems the error is caused by the plugin just invoking a straight out close without sending an EOF. net_disconnect(fd); That seems to be causing the error read unix /var/run/xapsd/xapsd.sock->@: read: connection reset by peer. Per the docs: Err returns the first non-EOF error that was encountered by the Scanner. So, when the plugin sees the OK, it needs to send an EOF to resolve the issue. Not sure how to change that yet.

from dovecot-xaps-daemon.

Ok... So I tried writing a EOF (char) 4 in the plugin back to the socket before the close. No change. I can't figure out who the culprit is since I can't read what's passing through the socket. Help?

from dovecot-xaps-daemon.

What dovecot version do you run?

from dovecot-xaps-daemon.

# dovecot --version
2.2.10

Last night I tried extensively to chase this down. WIthout monitoring the socket, I can't see if its the dovecot plugin that's not sending an EOF or what. I tried adding some code to send EOF before closing the socket but no change.

from dovecot-xaps-daemon.

Then it's probably related to this PR: st3fan/dovecot-xaps-plugin#15
Could you pls update to 2.2.11 or apply the attached patch (edit: to make things easier – https://github.com/dovecot/core/commit/e3d57448ca8612ebf4b7f652367c30562493860b.patch) to dovecot?

from dovecot-xaps-daemon.

I'm using the default CentOS 7 repos and it only has

dovecot.x86_64                                                                     1:2.2.10-7.el7                                                          @base

Do you know of a repo I can use other than having to manually rebuild it? Is there a way to confirm that the patch hasn't already been applied?

Last night I emailed the dovecot list trying to figure it out and was told by the dovecot team:
"Please don't use net_transmit, it's going away. You should use ostream
and istream instead."
I wonder if there are changes needed to work around their forthcoming code updates?

from dovecot-xaps-daemon.

I am not into CentOS - sorry. Could you post a link to that conversation here so I can create a new task?
You may try the plugin patch in that PR so you only have to compile the plugin again.

from dovecot-xaps-daemon.

I saw the change to the dovecot code but not the plugin. I'll go back and look at your link again. Perhaps I missed the plugin patch.
Here is the link to the thread I started on the dovecot list last night where they told me to use the ostream and istream. https://www.dovecot.org/pipermail/dovecot/2017-September/109293.html

from dovecot-xaps-daemon.

Ok, I see in your link where the patch is. I'll give that a shot. I see that its for the imap-xaps-plugin.c code. In doing my testing, I had to edit the xaps-plugin.c file on my setup. I'd assume the change goes to both. They're very similar. Is it really necessary for both?

from dovecot-xaps-daemon.

Could you please checkout a clean copy and apply the patch there – just to make sure nothing else is broken and we only test the patch.
Thanks

from dovecot-xaps-daemon.

Posted response to st3fan/dovecot-xaps-plugin#15
"I can confirm the patch to both imap-xaps-plugin.c and xaps-plugin.c work fine with dovecot 2.2.10-7 and dovecot 2.2.10-8 on CentOS 7 resolving the dreaded "connection reset by peer" error. Per the dovecot team, the plugin should be rewritten to use istream/ostream since they are going to deprecate their net_xxx from dovecot."

from dovecot-xaps-daemon.

So this can be closed, as this is a dovecot bug and the replacement of mentioned functions is tracked in the plugins bugtracker.
Thanks

from dovecot-xaps-daemon.

@st3fan can you please merge that patch into the plugin source? I missed that and it would have saved you and I both a couple months of this. :-) I'll have to be sure to check all closed items going forward.

from dovecot-xaps-daemon.

It's a workaround for a bug in dovecot. I don't think we should merge it as it's been fixed for 3 years upstream. I will add a note to the README.

from dovecot-xaps-daemon.

True, it's a bug in dovecot but there are many people like me that try to avoid manually building and/or installing RPMs for mainstream packages like dovecot. I wish I'd seen patch sooner because if you look at the history on my thread, this has been going on since 7/7. I'll see if I can somehow convince the CentOS 7 package maintainers to move to >= 2.2.11 going forward. They're still using 2.0.9 on CentOS 6! Wow... Thanks for your help!!!

from dovecot-xaps-daemon.

Maybe they can apply the patch I mentioned earlier? The bug is quite obvious and the patch is very small - shouldn't be a problem.
If not, I maybe create a seperate branch to support those old systems. Will think about that.

from dovecot-xaps-daemon.

Well, you could put in a compiler flag that looks at the version and if less than 2.2.11 it adds that in. I was looking up the proper syntax to make that request. It's low overhead and can save some sweat and tears. LOL.

from dovecot-xaps-daemon.

Please let us try to fix CentOS distribution first. Thanks

from dovecot-xaps-daemon.

I filed a bug on the package included in the CentOS 7 base distro. https://bugs.centos.org/view.php?id=13783 and also at https://bugzilla.redhat.com/show_bug.cgi?id=1489943. I found that GhettoForge has far newer versions available... http://mirror.ghettoforge.org/distributions/gf/el/7/plus/x86_64/ specifically http://mirror.ghettoforge.org/distributions/gf/el/7/plus/x86_64/dovecot22-2.2.31-3.gf.el7.x86_64.rpm which should definitely solve the problem. Preference would be to get the CentOS 7 team to include the newer versions already tried, trued and packaged by the Fedora team. I'll let you know if I hear anything.

from dovecot-xaps-daemon.