search

ppp-project / ppp

Paul's PPP Package: PPP daemon and associated utilities | Official GitHub repo: https://github.com/ppp-project/ppp
https://github.com/ppp-project/ppp
Other
384 stars 228 forks source link

xl2tpd and pppd running under qemu/kvm #92

Closed obluda closed 4 years ago

obluda commented 6 years ago

Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: message_type_avp: message type 12 (Incoming-Call-Connected) Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: tx_speed_avp: transmit baud rate is 100000000 Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: frame_type_avp: peer uses:sync frames Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: ignore_avp : Ignoring AVP Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: control_finish: message type is Incoming-Call-Connected(12). Tunnel is 23, call is 1. Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: start_pppd: I'm running: Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: "/usr/sbin/pppd" Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: "/dev/pts/1" Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: "passive" Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: "nodetach" Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: ":10.2.44.100" Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: "refuse-pap" Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: "debug" Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: "file" Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: "/etc/ppp/options.l2tpd" Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: Call established with 2.10.42.31, PID: 4948, Local: 62805, Remote: 1, Serial: 0 Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: network_thread: recv packet from 2.10.42.31, size = 12, tunnel = 29752, call = 0 ref=0 refhim=0 Feb 08 09:18:05 vpn xl2tpd[4907]: xl2tpd[4907]: network_thread: recv packet from 2.10.42.31, size = 33, tunnel = 29752, call = 62805 ref=0 refhim=0 Feb 08 09:18:05 vpn pppd[4948]: pppd 2.4.7 started by root, uid 0 Feb 08 09:18:05 vpn pppd[4948]: tcgetattr: Inappropriate ioctl for device (line 936) ) = 0 (Timeout)

[pid 4907] getpid() = 4907 [pid 4907] write(2, "xl2tpd[4907]: network_thread: se"..., 45) = 45 [pid 4907] select(6, [3 4 5], NULL, NULL, {tv_sec=0, tv_usec=3166}) = 0 (Timeout) [pid 4907] getpid() = 4907 [pid 4907] write(2, "xl2tpd[4907]: network_thread: se"..., 45) = 45 [pid 4907] select(6, [3 4 5], NULL, NULL, {tv_sec=58, tv_usec=997185} <unfinished ...> [pid 4948] <... nanosleep resumed> 0x7ffd7f5bf570) = 0 [pid 4948] close(8) = 0 [pid 4948] unlink("/var/lock/LCK..ppp") = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=192, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLK, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=944, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=944, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=164, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=164, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=192, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=440, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLK, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=760, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=760, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=164, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=164, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=440, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=528, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLK, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=892, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLK, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=892, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_WRLCK, l_whence=SEEK_SET, l_start=164, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=164, l_len=1}) = 0 [pid 4948] fcntl(7, F_SETLKW, {l_type=F_UNLCK, l_whence=SEEK_SET, l_start=528, l_len=1}) = 0 [pid 4948] getpid() = 4948 [pid 4948] sendto(3, "<30>Feb 8 09:18:06 pppd[4948]: "..., 37, MSG_NOSIGNAL, NULL, 0) = 37 [pid 4948] exit_group(1) = ? [pid 4948] +++ exited with 1 +++ <... select resumed> ) = 1 (in [5], left {tv_sec=58, tv_usec=829872}) --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=4948, si_uid=0, si_status=1, si_utime=0, si_stime=0} --- rt_sigreturn({mask=[]}) = 1 read(5, 0x55f04fe67324, 4096) = -1 EIO (Input/output error) wait4(-1, [{WIFEXITED(s) && WEXITSTATUS(s) == 1}], WNOHANG, NULL) = 4948 getpid() = 4907 write(2, "xl2tpd[4907]: child_handler : pp"..., 65) = 65 close(5) = 0 --- SIGHUP {si_signo=SIGHUP, si_code=SI_KERNEL} --- --- SIGCONT {si_signo=SIGCONT, si_code=SI_KERNEL} --- rt_sigreturn({mask=[]}) = 0 wait4(-1, 0x7fff48b1f004, WNOHANG, NULL) = -1 ECHILD (No child processes) sendmsg(3, {msg_name={sa_family=AF_INET, sin_port=htons(1701), sin_addr=inet_addr("2.10.42.31")}, msg_namelen=16, msg_iov=[{iov_base="\310\2\0&\0\27\0\1\0\2\0\4\200\10\0\0\0\0\0\16\200\n\0\0\0\1\0\1\0\0\200\10"..., iov_len=38}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, cmsg_data={ipi_ifindex=if_nametoindex("ens3"), ipi_spec_dst=inet_addr("10.2.42.49"), ipi_addr=inet_addr("10.2.42.49")}}], msg_controllen=28, msg_flags=0}, 0) = 38 getpid() = 4907 write(2, "xl2tpd[4907]: call_close: Call 6"..., 64) = 64 select(5, [3 4], NULL, NULL, {tv_sec=0, tv_usec=998858}) = 1 (in [3], left {tv_sec=0, tv_usec=998855}) recvmsg(3, {msg_name={sa_family=AF_INET, sin_port=htons(1701), sin_addr=inet_addr("2.10.42.31")}, msg_namelen=16, msg_iov=[{iov_base="\310\2\0\ft8\0\0\0\4\0\3", iov_len=4086}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, cmsg_data={ipi_ifindex=if_nametoindex("ens3"), ipi_spec_dst=inet_addr("10.2.42.49"), ipi_addr=inet_addr("10.2.42.49")}}], msg_controllen=32, msg_flags=0}, 0) = 12 getpid() = 4907 write(2, "xl2tpd[4907]: network_thread: re"..., 110) = 110 select(5, [3 4], NULL, NULL, {tv_sec=0, tv_usec=998565}) = 1 (in [3], left {tv_sec=0, tv_usec=998563}) recvmsg(3, {msg_name={sa_family=AF_INET, sin_port=htons(1701), sin_addr=inet_addr("2.10.42.31")}, msg_namelen=16, msg_iov=[{iov_base="\310\2\0&t8\0\0\0\4\0\3\200\10\0\0\0\0\0\4\200\10\0\0\0\t\0\27\200\n\0\0"..., iov_len=4086}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, cmsg_data={ipi_ifindex=if_nametoindex("ens3"), ipi_spec_dst=inet_addr("10.2.42.49"), ipi_addr=inet_addr("10.2.42.49")}}], msg_controllen=32, msg_flags=0}, 0) = 38 getpid() = 4907 write(2, "xl2tpd[4907]: network_thread: re"..., 110) = 110 getpid() = 4907 write(2, "xl2tpd[4907]: message_type_avp: "..., 86) = 86 getpid() = 4907 write(2, "xl2tpd[4907]: assigned_tunnel_av"..., 58) = 58 getpid() = 4907 write(2, "xl2tpd[4907]: result_code_avp: p"..., 102) = 102 getpid() = 4907 write(2, "xl2tpd[4907]: control_finish: me"..., 113) = 113 getpid() = 4907 write(2, "xl2tpd[4907]: control_finish: Co"..., 102) = 102 sendmsg(3, {msg_name={sa_family=AF_INET, sin_port=htons(1701), sin_addr=inet_addr("2.10.42.31")}, msg_namelen=16, msg_iov=[{iov_base="\310\2\0\f\0\27\0\0\0\3\0\5", iov_len=12}], msg_iovlen=1, msg_control=[{cmsg_len=28, cmsg_level=SOL_IP, cmsg_type=IP_PKTINFO, cmsg_data={ipi_ifindex=if_nametoindex("ens3"), ipi_spec_dst=inet_addr("10.2.42.49"), ipi_addr=inet_addr("10.2.42.49")}}], msg_controllen=28, msg_flags=0}, 0) = 12 getpid() = 4907 write(2, "xl2tpd[4907]: build_fdset: closi"..., 53) = 53 getpid() = 4907 write(2, "xl2tpd[4907]: Terminating pppd: "..., 64) = 64 kill(4948, SIGTERM) = -1 ESRCH (No such process) select(5, [3 4], NULL, NULL, NULLFeb 08 09:18:06 vpn charon[337]: 11[NET] received packet: from 2.10.42.31[500] to 10.2.42.49[500] (68 bytes) Feb 08 09:18:06 vpn xl2tpd[4907]: xl2tpd[4907]: network_thread: select timeout

Thanks, Regards,

obluda commented 6 years ago

Sorry about that. Related part of the trace was elsewhere:

[pid 746] openat(AT_FDCWD, "/dev/ppp", O_RDWR|O_NONBLOCK) = 8 [pid 746] fcntl(8, F_GETFL) = 0x8802 (flags O_RDWR|O_NONBLOCK|O_LARGEFILE) [pid 746] fcntl(8, F_SETFL, O_RDWR|O_LARGEFILE) = 0 [pid 746] ioctl(8, TIOCMBIS, [TIOCM_DTR]) = -1 ENOTTY (Inappropriate ioctl for device) [pid 746] ioctl(8, TCGETS, 0x7fff80622830) = -1 ENOTTY (Inappropriate ioctl for device) [pid 746] getpid() = 746 [pid 746] sendto(3, "<27>Feb 10 21:22:15 pppd[746]: t"..., 83, MSG_NOSIGNAL, NULL, 0) = 83 [pid 746] write(1, "tcgetattr: Inappropriate ioctl f"..., 52) = 52 [pid 746] write(1, "\n", 1) = 1 [pid 746] ioctl(8, TIOCMBIC, [TIOCM_DTR]) = -1 ENOTTY (Inappropriate ioctl for device) [pid 746] nanosleep({tv_sec=1, tv_nsec=0}, <unfinished ...> [pid 734] <... select resumed> ) = 1 (in [5], left {tv_sec=0, tv_usec=844026}) [pid 734] read(5, "tcgetattr: Inappropriate ioctl f"..., 4096) = 54 [pid 734] read(5, 0x5652f1370324, 4096) = -1 EAGAIN (Resource temporarily unavailable) [pid 734] gettimeofday({tv_sec=1518297735, tv_usec=53508}, NULL) = 0 [pid 734] select(6, [3 4 5], NULL, NULL, {tv_sec=0, tv_usec=842904}

paulusmack commented 4 years ago

You have the word "ppp" in /etc/ppp/options.l2tpd. That makes pppd think you want to use /dev/ppp as the serial device, and that doesn't work. You actually mean to use /dev/pts/1. Take out the "ppp" word from /etc/ppp/options.l2tpd.

Closing as user error.